hbase-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Andrew Purtell <apurt...@apache.org>
Subject master fails to reassign regions from dead RS?
Date Sat, 19 Jun 2010 20:46:49 GMT
Sorry, stuck in airport about to get on planes for 24 hours+ with limited time.

Full logs available at:  https://tm-files.s3.amazonaws.com/20100618-test0-webtable-crash.tar.bz2

I witnessed a problem while testing the latest build of our TM-2 HBase+Hadoop internal distribution
last night. TM-2 is HBase 0.20.5-dev (the latest RC) with no HBase patches. Where we diverge
from upstream for this build is HDFS: we use Hadoop 0.20.2 plus 0.20-append branch changesets
plus a couple of other HDFS patches. 

The divergence between our branch and upstream may ONLY be material with regards to why a
region server crashed. (Separate issue I am looking into.) What I am reporting now is a possible
problem with the master. 

As far as I can see, in this test scenario the master never reassigns regions away from a
crashed RS. 


***
CLIENT

The client sees the RS hosting ROOT and META die.

10/06/19 07:59:38 DEBUG client.HConnectionManager$TableServers: locateRegionInMeta attempt
0 of 10 failed; retrying after sleep of 1000 because: Call to /10.222.238.255:60020 failed
on local exception: java.io.EOFException
10/06/19 07:59:38 DEBUG client.HConnectionManager$TableServers: Removed .META.,,1 for tableName=.META.
from cache because of TestTable,9f9a5c1e-f4c3-b955-85b2-f60636a9cb25,99999999999999
10/06/19 07:59:38 DEBUG client.HConnectionManager$TableServers: locateRegionInMeta attempt
0 of 10 failed; retrying after sleep of 1000 because: Connection refused
10/06/19 07:59:38 DEBUG zookeeper.ZooKeeperWrapper: Read ZNode /hbase/root-region-server got
10.222.238.255:60020
10/06/19 07:59:38 DEBUG client.HConnectionManager$TableServers: Root region location changed.
Sleeping.

***
MASTER

HMaster also sees the RS hosting ROOT and META die.

2010-06-19 07:59:35,424 INFO org.apache.hadoop.hbase.master.ServerManager: Processing MSG_REPORT_OPEN:
TestTable,8b241b8b-4ab0-f252-8d18-0949c7a918bf,1276948774514 from domU-12-31-38-04-ED-D1.compute-1.internal,60020,1276920183192;
1 of 1
2010-06-19 07:59:35,625 INFO org.apache.hadoop.hbase.master.RegionServerOperation: Updated
row TestTable,8b35278f-56fa-4955-93fe-2ff7c4163dc3,1276948774514 in region .META.,,1 with
startcode=1276920183192, server=10.220.238.31:60020
2010-06-19 07:59:35,625 INFO org.apache.hadoop.hbase.master.RegionServerOperation: TestTable,8b241b8b-4ab0-f252-8d18-0949c7a918bf,1276948774514
open on 10.220.238.31:60020
2010-06-19 07:59:35,704 INFO org.apache.hadoop.hbase.master.RegionServerOperation: Updated
row TestTable,8b241b8b-4ab0-f252-8d18-0949c7a918bf,1276948774514 in region .META.,,1 with
startcode=1276920183192, server=10.220.238.31:60020
2010-06-19 08:00:04,370 INFO org.apache.hadoop.hbase.master.BaseScanner: RegionManager.rootScanner
scanning meta region {server: 10.222.238.255:60020, regionname: -ROOT-,,0, startKey: <>}
2010-06-19 08:00:04,373 WARN org.apache.hadoop.hbase.master.BaseScanner: Scan ROOT region
java.net.ConnectException: Connection refused
	at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
	at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:574)
	at org.apache.hadoop.net.SocketIOWithTimeout.connect(SocketIOWithTimeout.java:206)
	at org.apache.hadoop.net.NetUtils.connect(NetUtils.java:404)
	at org.apache.hadoop.hbase.ipc.HBaseClient$Connection.setupIOstreams(HBaseClient.java:308)
	at org.apache.hadoop.hbase.ipc.HBaseClient.getConnection(HBaseClient.java:843)
	at org.apache.hadoop.hbase.ipc.HBaseClient.call(HBaseClient.java:715)
	at org.apache.hadoop.hbase.ipc.HBaseRPC$Invoker.invoke(HBaseRPC.java:333)
	at $Proxy1.openScanner(Unknown Source)
	at org.apache.hadoop.hbase.master.BaseScanner.scanRegion(BaseScanner.java:177)
	at org.apache.hadoop.hbase.master.RootScanner.scanRoot(RootScanner.java:54)
	at org.apache.hadoop.hbase.master.RootScanner.maintenanceScan(RootScanner.java:79)
	at org.apache.hadoop.hbase.master.BaseScanner.chore(BaseScanner.java:153)
	at org.apache.hadoop.hbase.Chore.run(Chore.java:68)
2010-06-19 08:00:04,532 INFO org.apache.hadoop.hbase.master.ServerManager: 5 region servers,
0 dead, average load 456.4
2010-06-19 08:00:07,399 INFO org.apache.hadoop.hbase.master.BaseScanner: RegionManager.metaScanner
scanning meta region {server: 10.222.238.255:60020, regionname: .META.,,1, startKey: <>}
2010-06-19 08:00:07,400 WARN org.apache.hadoop.hbase.master.BaseScanner: Scan one META region:
{server: 10.222.238.255:60020, regionname: .META.,,1, startKey: <>}
java.net.ConnectException: Connection refused
	at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
	at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:574)
	at org.apache.hadoop.net.SocketIOWithTimeout.connect(SocketIOWithTimeout.java:206)
	at org.apache.hadoop.net.NetUtils.connect(NetUtils.java:404)
	at org.apache.hadoop.hbase.ipc.HBaseClient$Connection.setupIOstreams(HBaseClient.java:308)
	at org.apache.hadoop.hbase.ipc.HBaseClient.getConnection(HBaseClient.java:843)
	at org.apache.hadoop.hbase.ipc.HBaseClient.call(HBaseClient.java:715)
	at org.apache.hadoop.hbase.ipc.HBaseRPC$Invoker.invoke(HBaseRPC.java:333)
	at $Proxy1.openScanner(Unknown Source)
	at org.apache.hadoop.hbase.master.BaseScanner.scanRegion(BaseScanner.java:177)
	at org.apache.hadoop.hbase.master.MetaScanner.scanOneMetaRegion(MetaScanner.java:73)
	at org.apache.hadoop.hbase.master.MetaScanner.maintenanceScan(MetaScanner.java:129)
	at org.apache.hadoop.hbase.master.BaseScanner.chore(BaseScanner.java:153)
	at org.apache.hadoop.hbase.Chore.run(Chore.java:68)
2010-06-19 08:00:07,407 INFO org.apache.hadoop.hbase.master.BaseScanner: All 1 .META. region(s)
scanned
2010-06-19 08:00:29,708 INFO org.apache.hadoop.hbase.master.ServerManager: domU-12-31-38-06-EC-F1.compute-1.internal,60020,1276920180076
znode expired
2010-06-19 08:00:29,710 INFO org.apache.hadoop.hbase.master.RegionManager: -ROOT- region unset
(but not set to be reassigned)
2010-06-19 08:00:29,710 INFO org.apache.hadoop.hbase.master.RegionManager: META region removed
from onlineMetaRegions
2010-06-19 08:00:29,711 INFO org.apache.hadoop.hbase.master.RegionServerOperation: process
shutdown of server domU-12-31-38-06-EC-F1.compute-1.internal,60020,1276920180076: logSplit:
false, rootRescanned: false, numberOfMetaRegions: 1, onlineMetaRegions.size(): 0
2010-06-19 08:00:29,756 INFO org.apache.hadoop.hbase.regionserver.HLog: Splitting 38 hlog(s)
in hdfs://domU-12-31-38-06-EC-81.compute-1.internal:8020/hbase/.logs/domU-12-31-38-06-EC-F1.compute-1.internal,60020,1276920180076
2010-06-19 08:00:34,979 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:00:38,418 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:00:42,021 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:00:47,539 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:00:49,649 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:00:51,761 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:00:57,992 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:00,297 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:02,206 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:04,827 INFO org.apache.hadoop.hbase.master.ServerManager: 4 region servers,
1 dead, average load 456.25[domU-12-31-38-06-EC-F1.compute-1.internal,60020,1276920180076]
2010-06-19 08:01:07,690 INFO org.apache.hadoop.hbase.master.BaseScanner: All 0 .META. region(s)
scanned
2010-06-19 08:01:08,042 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:09,670 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:11,710 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:16,659 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:19,058 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:20,908 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:25,805 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:27,674 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:29,533 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:33,806 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:36,320 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:38,512 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:44,046 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:46,109 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:48,316 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:54,333 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:56,089 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:01:58,738 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:02:03,269 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:02:04,829 INFO org.apache.hadoop.hbase.master.ServerManager: 4 region servers,
1 dead, average load 456.25[domU-12-31-38-06-EC-F1.compute-1.internal,60020,1276920180076]
2010-06-19 08:02:04,908 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:02:07,420 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:02:07,692 INFO org.apache.hadoop.hbase.master.BaseScanner: All 0 .META. region(s)
scanned
2010-06-19 08:02:12,709 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:02:15,076 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:02:18,160 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:02:23,213 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:02:25,326 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:02:27,388 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:02:31,922 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:02:32,584 INFO org.apache.hadoop.hbase.regionserver.HLog: Failed open for append,
waiting on lease recovery: hdfs://domU-12-31-38-06-EC-81.compute-1.internal/hbase/.logs/domU-12-31-38-06-EC-F1.compute-1.internal,60020,1276920180076/hlog.dat.1276948769573
org.apache.hadoop.ipc.RemoteException: org.apache.hadoop.hdfs.protocol.AlreadyBeingCreatedException:
failed to create file /hbase/.logs/domU-12-31-38-06-EC-F1.compute-1.internal,60020,1276920180076/hlog.dat.1276948769573
for DFSClient_1937332980 on client 10.222.239.111, because this file is already being created
by NN_Recovery on 10.222.238.255
	at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.startFileInternal(FSNamesystem.java:1166)
	at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.appendFile(FSNamesystem.java:1258)
	at org.apache.hadoop.hdfs.server.namenode.NameNode.append(NameNode.java:396)
	at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:508)
	at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1044)
	at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1040)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.security.auth.Subject.doAs(Subject.java:396)
	at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1038)

	at org.apache.hadoop.ipc.Client.call(Client.java:740)
	at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:220)
	at $Proxy0.append(Unknown Source)
	at sun.reflect.GeneratedMethodAccessor11.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:82)
	at org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:59)
	at $Proxy0.append(Unknown Source)
	at org.apache.hadoop.hdfs.DFSClient.append(DFSClient.java:521)
	at org.apache.hadoop.hdfs.DistributedFileSystem.append(DistributedFileSystem.java:186)
	at org.apache.hadoop.fs.FileSystem.append(FileSystem.java:530)
	at org.apache.hadoop.hbase.regionserver.HLog.recoverLog(HLog.java:1203)
	at org.apache.hadoop.hbase.regionserver.HLog.splitLog(HLog.java:959)
	at org.apache.hadoop.hbase.regionserver.HLog.splitLog(HLog.java:872)
	at org.apache.hadoop.hbase.master.ProcessServerShutdown.process(ProcessServerShutdown.java:298)
	at org.apache.hadoop.hbase.master.HMaster.processToDoQueue(HMaster.java:497)
	at org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:432)
2010-06-19 08:02:33,591 INFO org.apache.hadoop.hbase.regionserver.HLog: Failed open for append,
waiting on lease recovery: hdfs://domU-12-31-38-06-EC-81.compute-1.internal/hbase/.logs/domU-12-31-38-06-EC-F1.compute-1.internal,60020,1276920180076/hlog.dat.1276948769573
org.apache.hadoop.ipc.RemoteException: org.apache.hadoop.hdfs.protocol.AlreadyBeingCreatedException:
failed to create file /hbase/.logs/domU-12-31-38-06-EC-F1.compute-1.internal,60020,1276920180076/hlog.dat.1276948769573
for DFSClient_1937332980 on client 10.222.239.111, because this file is already being created
by NN_Recovery on 10.222.238.255
	at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.startFileInternal(FSNamesystem.java:1166)
	at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.appendFile(FSNamesystem.java:1258)
	at org.apache.hadoop.hdfs.server.namenode.NameNode.append(NameNode.java:396)
	at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:508)
	at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1044)
	at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1040)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.security.auth.Subject.doAs(Subject.java:396)
	at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1038)

	at org.apache.hadoop.ipc.Client.call(Client.java:740)
	at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:220)
	at $Proxy0.append(Unknown Source)
	at sun.reflect.GeneratedMethodAccessor11.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:82)
	at org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:59)
	at $Proxy0.append(Unknown Source)
	at org.apache.hadoop.hdfs.DFSClient.append(DFSClient.java:521)
	at org.apache.hadoop.hdfs.DistributedFileSystem.append(DistributedFileSystem.java:186)
	at org.apache.hadoop.fs.FileSystem.append(FileSystem.java:530)
	at org.apache.hadoop.hbase.regionserver.HLog.recoverLog(HLog.java:1203)
	at org.apache.hadoop.hbase.regionserver.HLog.splitLog(HLog.java:959)
	at org.apache.hadoop.hbase.regionserver.HLog.splitLog(HLog.java:872)
	at org.apache.hadoop.hbase.master.ProcessServerShutdown.process(ProcessServerShutdown.java:298)
	at org.apache.hadoop.hbase.master.HMaster.processToDoQueue(HMaster.java:497)
	at org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:432)
2010-06-19 08:02:34,597 INFO org.apache.hadoop.hbase.regionserver.HLog: Failed open for append,
waiting on lease recovery: hdfs://domU-12-31-38-06-EC-81.compute-1.internal/hbase/.logs/domU-12-31-38-06-EC-F1.compute-1.internal,60020,1276920180076/hlog.dat.1276948769573
org.apache.hadoop.ipc.RemoteException: org.apache.hadoop.hdfs.protocol.AlreadyBeingCreatedException:
failed to create file /hbase/.logs/domU-12-31-38-06-EC-F1.compute-1.internal,60020,1276920180076/hlog.dat.1276948769573
for DFSClient_1937332980 on client 10.222.239.111, because this file is already being created
by NN_Recovery on 10.222.238.255
	at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.startFileInternal(FSNamesystem.java:1166)
	at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.appendFile(FSNamesystem.java:1258)
	at org.apache.hadoop.hdfs.server.namenode.NameNode.append(NameNode.java:396)
	at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:508)
	at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1044)
	at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1040)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.security.auth.Subject.doAs(Subject.java:396)
	at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1038)

	at org.apache.hadoop.ipc.Client.call(Client.java:740)
	at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:220)
	at $Proxy0.append(Unknown Source)
	at sun.reflect.GeneratedMethodAccessor11.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:82)
	at org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:59)
	at $Proxy0.append(Unknown Source)
	at org.apache.hadoop.hdfs.DFSClient.append(DFSClient.java:521)
	at org.apache.hadoop.hdfs.DistributedFileSystem.append(DistributedFileSystem.java:186)
	at org.apache.hadoop.fs.FileSystem.append(FileSystem.java:530)
	at org.apache.hadoop.hbase.regionserver.HLog.recoverLog(HLog.java:1203)
	at org.apache.hadoop.hbase.regionserver.HLog.splitLog(HLog.java:959)
	at org.apache.hadoop.hbase.regionserver.HLog.splitLog(HLog.java:872)
	at org.apache.hadoop.hbase.master.ProcessServerShutdown.process(ProcessServerShutdown.java:298)
	at org.apache.hadoop.hbase.master.HMaster.processToDoQueue(HMaster.java:497)
	at org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:432)
2010-06-19 08:02:36,330 INFO org.apache.hadoop.hbase.regionserver.HLog: Past out lease recovery
2010-06-19 08:02:49,498 INFO org.apache.hadoop.hbase.regionserver.HLog: hlog file splitting
completed in 139783 millis for hdfs://domU-12-31-38-06-EC-81.compute-1.internal:8020/hbase/.logs/domU-12-31-38-06-EC-F1.compute-1.internal,60020,1276920180076
2010-06-19 08:02:49,498 INFO org.apache.hadoop.hbase.master.RegionServerOperation: Log split
complete, meta reassignment and scanning:

*** Log recovery complete.

2010-06-19 08:02:49,498 INFO org.apache.hadoop.hbase.master.RegionServerOperation: ProcessServerShutdown
reassigning ROOT region
2010-06-19 08:02:49,498 INFO org.apache.hadoop.hbase.master.RegionManager: -ROOT- region unset
(but not set to be reassigned)
2010-06-19 08:02:49,498 INFO org.apache.hadoop.hbase.master.RegionManager: ROOT inserted into
regionsInTransition
2010-06-19 08:02:49,498 INFO org.apache.hadoop.hbase.master.RegionServerOperation: ProcessServerShutdown
setting to unassigned: {server: 10.222.238.255:60020, regionname: .META.,,1, startKey: <>}
2010-06-19 08:02:49,724 INFO org.apache.hadoop.hbase.master.RegionManager: Assigning region
-ROOT-,,0 to domU-12-31-38-01-71-B1.compute-1.internal,60020,1276920193543
2010-06-19 08:02:49,796 INFO org.apache.hadoop.hbase.master.ServerManager: Processing MSG_REPORT_OPEN:
-ROOT-,,0 from domU-12-31-38-01-71-B1.compute-1.internal,60020,1276920193543; 1 of 1

*** ROOT is reopened

2010-06-19 08:02:49,800 INFO org.apache.hadoop.hbase.master.BaseScanner: RegionManager.rootScanner
scanning meta region {server: 10.253.118.63:60020, regionname: -ROOT-,,0, startKey: <>}
2010-06-19 08:02:49,854 INFO org.apache.hadoop.hbase.master.BaseScanner: RegionManager.rootScanner
scan of 1 row(s) of meta region {server: 10.253.118.63:60020, regionname: -ROOT-,,0, startKey:
<>} complete
2010-06-19 08:02:49,854 INFO org.apache.hadoop.hbase.master.BaseScanner: RegionManager.rootScanner
scanning meta region {server: 10.253.118.63:60020, regionname: -ROOT-,,0, startKey: <>}
2010-06-19 08:02:49,861 INFO org.apache.hadoop.hbase.master.BaseScanner: RegionManager.rootScanner
scan of 1 row(s) of meta region {server: 10.253.118.63:60020, regionname: -ROOT-,,0, startKey:
<>} complete
2010-06-19 08:02:49,888 INFO org.apache.hadoop.hbase.master.RegionManager: Assigning region
.META.,,1 to domU-12-31-38-04-ED-D1.compute-1.internal,60020,1276920183192
2010-06-19 08:03:04,831 INFO org.apache.hadoop.hbase.master.ServerManager: 4 region servers,
1 dead, average load 456.5[domU-12-31-38-06-EC-F1.compute-1.internal,60020,1276920180076]
2010-06-19 08:03:07,693 INFO org.apache.hadoop.hbase.master.BaseScanner: All 0 .META. region(s)
scanned
2010-06-19 08:03:11,618 INFO org.apache.hadoop.hbase.master.ServerManager: Processing MSG_REPORT_OPEN:
.META.,,1 from domU-12-31-38-04-ED-D1.compute-1.internal,60020,1276920183192; 1 of 1
2010-06-19 08:03:11,619 INFO org.apache.hadoop.hbase.master.RegionServerOperation: .META.,,1
open on 10.220.238.31:60020
2010-06-19 08:03:11,647 INFO org.apache.hadoop.hbase.master.RegionServerOperation: Updated
row .META.,,1 in region -ROOT-,,0 with startcode=1276920183192, server=10.220.238.31:60020

*** META is reopened


***
CLIENT

After ROOT and META are reopened

*** Finds new ROOT

10/06/19 08:02:53 DEBUG client.HConnectionManager$TableServers: Wake. Retry finding root region.
10/06/19 08:02:53 DEBUG zookeeper.ZooKeeperWrapper: Read ZNode /hbase/root-region-server got
10.253.118.63:60020
10/06/19 08:02:53 DEBUG client.HConnectionManager$TableServers: Found ROOT at 10.253.118.63:60020
10/06/19 08:02:53 DEBUG zookeeper.ZooKeeperWrapper: Read ZNode /hbase/root-region-server got
10.253.118.63:60020
10/06/19 08:02:53 DEBUG client.HConnectionManager$TableServers: Found ROOT at 10.253.118.63:60020

*** Finds new META

10/06/19 08:03:15 DEBUG client.HConnectionManager$TableServers: locateRegionInMeta attempt
8 of 10 failed; retrying after sleep of 16000 because: Connection refused
10/06/19 08:03:15 DEBUG client.HConnectionManager$TableServers: Removed .META.,,1 for tableName=.META.
from cache because of TestTable,aad6db21-f4c3-e255-96d1-3bc9a9339734,99999999999999
10/06/19 08:03:15 DEBUG client.HConnectionManager$TableServers: Cached location for .META.,,1
is 10.220.238.31:60020

*** Tries to relocate 00771560-c9e1-7a50-9183-ac99e0be03b8,1276935951367 which was hosted
on dead RS

10/06/19 08:04:10 DEBUG client.HConnectionManager$TableServers: Removed TestTable,00771560-c9e1-7a50-9183-ac99e0be03b8,1276935951367
for tableName=TestTable from cache because of 0094d9bd-41ad-8c51-a266-1e54a277d247
10/06/19 08:04:10 DEBUG client.HConnectionManager$TableServers: Cached location for TestTable,00771560-c9e1-7a50-9183-ac99e0be03b8,1276935951367
is 10.222.238.255:60020
10/06/19 08:04:10 DEBUG client.HConnectionManager$TableServers: Removed TestTable,00771560-c9e1-7a50-9183-ac99e0be03b8,1276935951367
for tableName=TestTable from cache because of 008169ff-7ad8-f05d-854f-954bc10de3f3

*** Still trying hours later (this region among others)

10/06/19 11:38:08 DEBUG client.HConnectionManager$TableServers: Cached location for TestTable,00771560-c9e1-7a50-9183-ac99e0be03b8,1276935951367
is 10.222.238.255:60020
10/06/19 11:38:08 DEBUG client.HConnectionManager$TableServers: Removed TestTable,00771560-c9e1-7a50-9183-ac99e0be03b8,1276935951367
for tableName=TestTable from cache because of 008169ff-7ad8-f05d-854f-954bc10de3f3
10/06/19 11:38:08 DEBUG client.HConnectionManager$TableServers: Cached location for TestTable,00771560-c9e1-7a50-9183-ac99e0be03b8,1276935951367
is 10.222.238.255:60020


***
MASTER

So what happend with TestTable,00771560-c9e1-7a50-9183-ac99e0be03b8,1276935951367?

This is the last entry in the master log regarding this region:

2010-06-19 04:25:55,646 INFO org.apache.hadoop.hbase.master.RegionServerOperation: TestTable,00771560-c9e1-7a50-9183-ac99e0be03b8,1276935951367
open on 10.222.238.255:60020
2010-06-19 04:25:55,663 INFO org.apache.hadoop.hbase.master.RegionServerOperation: Updated
row TestTable,00771560-c9e1-7a50-9183-ac99e0be03b8,1276935951367 in region .META.,,1 with
startcode=1276920180076, server=10.222.238.255:60020

The RS failure happened around 10/06/19 07:59

The master never tries to reassign this or other regions hosted on the dead RS.

Master processes MSG_REPORT_SPLIT_INCLUDES_DAUGHTERS that come in over time from this point.
However, never a MSG_REPORT_OPEN, or CLOSE either.

Do I have this right?

I admit I've gone through these logs hastily as I'm pressed for time.

   - Andy



      


Mime
View raw message