You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@hbase.apache.org by Gaojinchao <ga...@huawei.com> on 2011/05/25 06:27:42 UTC

About RegionServer checkin

If Region server checkin after call this.serverManager.waitForRegionServers().
It seems that regionServerReport shouldn't add Region server to onlineServers.
Otherwise The region may be opened again.


In my cluster:
2011-05-23 10:56:30,726 INFO org.apache.hadoop.hbase.master.HMaster: Master startup proceeding: cluster startup
2011-05-23 10:56:30,726 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Deleting any existing unassigned nodes

// Region server register later , So the 1344 regions had opened in other region server.
 So, I think it should shutdown machine 158-1-101-82.

2011-05-23 10:56:33,504 INFO org.apache.hadoop.hbase.master.ServerManager: Registerring server=158-1-101-82,20020,1306117051387, regionCount=1344, userLoad=true
2011-05-23 10:56:33,875 INFO org.apache.hadoop.hbase.master.AssignmentManager: Bulk assigning 5041 region(s) across 1 server(s), retainAssignment=true
2011-05-23 10:56:33,876 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Timeout-on-RIT=5041000
2011-05-23 10:56:33,876 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Bulk assigning 5041 region(s) to 158-1-101-222,20020,1306119315097

Re: About RegionServer checkin

Posted by Gaojinchao <ga...@huawei.com>.
Yes, But It is later. 
Look this log: 
all regions was opened in regin server 158-1-101-222
,876 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Timeout-on-RIT=5041000
2011-05-23 10:56:33,876 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Bulk assigning 5041 region(s) to 158-1-101-222,20020,1306119315097



-----邮件原件-----
发件人: Ted Yu [mailto:yuzhihong@gmail.com] 
发送时间: 2011年5月27日 11:08
收件人: user@hbase.apache.org
主题: Re: About RegionServer checkin

>> 2011-05-23 10:56:33,504 INFO
org.apache.hadoop.hbase.master.ServerManager: Registering
server=158-1-101-82,20020,1306117051387, regionCount=1344, userLoad=true

For the above log, ServerManager would execute this in recordNewServer():
    LOG.info("Registering server=" + serverName);
    this.onlineServers.put(serverName, hsl);
It was called by regionServerReport().

2011/5/26 Gaojinchao <ga...@huawei.com>

> Thanks for your reply. I understand your mean.
> But It is not enough.
> This is log.
>
> Hmaster log:
> 2011-05-23 10:56:17,326 INFO org.apache.hadoop.hbase.master.ServerManager:
> Waiting on regionserver(s) to checkin
> 2011-05-23 10:56:18,393 INFO org.apache.hadoop.hbase.master.ServerManager:
> Registering server=158-1-101-222,20020,1306119315097, regionCount=0,
> userLoad=false
> 2011-05-23 10:56:18,826 INFO org.apache.hadoop.hbase.master.ServerManager:
> Waiting on regionserver(s) count to settle; currently=1
> 2011-05-23 10:56:20,326 INFO org.apache.hadoop.hbase.master.ServerManager:
> Finished waiting for regionserver count to settle; count=1, sleptFor=19500
> 2011-05-23 10:56:20,326 INFO org.apache.hadoop.hbase.master.ServerManager:
> Exiting wait on regionserver(s) to checkin; count=1, stopped=false, count of
> regions out on cluster=0
> 2011-05-23 10:56:20,329 INFO
> org.apache.hadoop.hbase.master.MasterFileSystem: Log folder hdfs://
> 158.1.101.82:9000/hbase/.logs/158-1-101-222,20020,1306111562081 doesn't
> belong to a known region server, splitting
> 2011-05-23 10:56:20,341 INFO
> org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Splitting 2 hlog(s)
> in hdfs://158.1.101.82:9000/hbase/.logs/158-1-101-222,20020,1306111562081
> 2011-05-23<http://158.1.101.82:9000/hbase/.logs/158-1-101-222,20020,1306111562081%0A2011-05-23>10:56:20,342 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter:
> Writer thread Thread[WriterThread-0,5,main]: starting
> .......
> 2011-05-23 10:56:25,152 INFO
> org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Waiting for split
> writer threads to finish
> 2011-05-23 10:56:25,983 INFO
> org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Split writers
> finished
> 2011-05-23 10:56:25,983 INFO
> org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: hlog file splitting
> completed in 2004 ms for hdfs://
> 158.1.101.82:9000/hbase/.logs/158-1-101-82,20020,1306117051387
> 2011-05-23<http://158.1.101.82:9000/hbase/.logs/158-1-101-82,20020,1306117051387%0A2011-05-23>10:56:29,032 WARN
> org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation:
> RemoteException connecting to RS
> org.apache.hadoop.ipc.RemoteException:
> org.apache.hadoop.hbase.ipc.ServerNotRunningException: Server is not running
> yet
>        at
> org.apache.hadoop.hbase.master.HMaster.assignRootAndMeta(HMaster.java:431)
>        at
> org.apache.hadoop.hbase.master.HMaster.finishInitialization(HMaster.java:389)
>        at org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:283)
> 2011-05-23 10:56:29,034 INFO
> org.apache.hadoop.hbase.catalog.RootLocationEditor: Unsetting ROOT region
> location in ZooKeeper
> 2011-05-23 10:56:29,058 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Creating
> (or updating) unassigned node for 70236052 with OFFLINE state
> 2011-05-23 10:56:29,071 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: 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=158-1-101-222,20020,1306119315097; 1 (online=1, exclude=null) available
> servers
> 2011-05-23 10:56:29,071 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
> -ROOT-,,0.70236052 to 158-1-101-222,20020,1306119315097
> 2011-05-23 10:56:29,071 DEBUG org.apache.hadoop.hbase.master.ServerManager:
> New connection to 158-1-101-222,20020,1306119315097
> 2011-05-23 10:56:29,095 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097,
> region=70236052/-ROOT-
> 2011-05-23 10:56:29,208 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097,
> region=70236052/-ROOT-
> 2011-05-23 10:56:29,220 INFO org.apache.hadoop.hbase.master.HMaster: -ROOT-
> assigned=1, rit=false, location=158-1-101-222:20020
> 2011-05-23 10:56:29,233 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> transition=RS_ZK_REGION_OPENED, server=158-1-101-222,20020,1306119315097,
> region=70236052/-ROOT-
> 2011-05-23 10:56:29,236 DEBUG
> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Handling OPENED
> event for 70236052; deleting unassigned node
> 2011-05-23 10:56:29,236 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Deleting
> existing unassigned node for 70236052 that is in expected state
> RS_ZK_REGION_OPENED
> 2011-05-23 10:56:29,245 INFO
> org.apache.hadoop.hbase.catalog.CatalogTracker: Failed verification of
> .META.,,1 at address=null;
> org.apache.hadoop.hbase.NotServingRegionException:
> org.apache.hadoop.hbase.NotServingRegionException: Region is not online:
> .META.,,1
> 2011-05-23 10:56:29,245 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Creating
> (or updating) unassigned node for 1028785192 with OFFLINE state
> 2011-05-23 10:56:29,252 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006
> Successfully deleted unassigned node for region 70236052 in expected state
> RS_ZK_REGION_OPENED
> 2011-05-23 10:56:29,254 DEBUG
> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Opened region
> -ROOT-,,0.70236052 on 158-1-101-222,20020,1306119315097
> 2011-05-23 10:56:29,263 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> transition=M_ZK_REGION_OFFLINE, server=158-1-101-222:20000,
> region=1028785192/.META.
> 2011-05-23 10:56:29,263 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: 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=158-1-101-222,20020,1306119315097; 1 (online=1, exclude=null)
> available servers
> 2011-05-23 10:56:29,263 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
> .META.,,1.1028785192 to 158-1-101-222,20020,1306119315097
> 2011-05-23 10:56:29,278 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097,
> region=1028785192/.META.
> 2011-05-23 10:56:30,682 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097,
> region=1028785192/.META.
> 2011-05-23 10:56:30,711 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> transition=RS_ZK_REGION_OPENED, server=158-1-101-222,20020,1306119315097,
> region=1028785192/.META.
> 2011-05-23 10:56:30,712 DEBUG
> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Handling OPENED
> event for 1028785192; deleting unassigned node
> 2011-05-23 10:56:30,712 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Deleting
> existing unassigned node for 1028785192 that is in expected state
> RS_ZK_REGION_OPENED
> 2011-05-23 10:56:30,719 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006
> Successfully deleted unassigned node for region 1028785192 in expected state
> RS_ZK_REGION_OPENED
> 2011-05-23 10:56:30,719 DEBUG
> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Opened region
> .META.,,1.1028785192 on 158-1-101-222,20020,1306119315097
> 2011-05-23 10:56:30,719 INFO
> org.apache.hadoop.hbase.zookeeper.MetaNodeTracker: Detected completed
> assignment of META, notifying catalog tracker
> 2011-05-23 10:56:30,726 INFO org.apache.hadoop.hbase.master.HMaster: .META.
> assigned=2, rit=false, location=158-1-101-222:20020
> 2011-05-23 10:56:30,726 INFO org.apache.hadoop.hbase.master.HMaster: Master
> startup proceeding: cluster startup
> 2011-05-23 10:56:30,726 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Deleting
> any existing unassigned nodes
>
> // regionserver(158-1-101-82) Registered
> 2011-05-23 10:56:33,504 INFO org.apache.hadoop.hbase.master.ServerManager:
> Registering server=158-1-101-82,20020,1306117051387, regionCount=1344,
> userLoad=true
> 2011-05-23 10:56:33,875 INFO
> org.apache.hadoop.hbase.master.AssignmentManager: Bulk assigning 5041
> region(s) across 1 server(s), retainAssignment=true
> 2011-05-23 10:56:33,876 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Timeout-on-RIT=5041000
>
> //regions was opened in 158-1-101-222 machine
> 2011-05-23 10:56:33,876 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Bulk assigning 5041
> region(s) to 158-1-101-222,20020,1306119315097
> 2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for b18eba004dfe6b1224f16a275ec342d1 with OFFLINE
> state
> 2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for 43b4b419baec6114a9afbc1432d17856 with OFFLINE
> state
> 2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for 17eb7fc069d11de1d403499caff024e4 with OFFLINE
> state
> 2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for ef4ec24ce49e31ec2c5c51a4acc76e4e with OFFLINE
> state
> 2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for 86e6193a18c887a2ebcaf7c409ac7c5f with OFFLINE
> state
> 2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for 5f81b6cecf483f0f8b26fce5b7040078 with OFFLINE
> state
> 2011-05-23 10:56:33,936 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for faf9d38383ac7d8d594743e8aee400e3 with OFFLINE
> state
> 2011-05-23 10:56:33,936 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for 52a547b878ca41dc1a6fbf84800bf1c3 with OFFLINE
> state
> 2011-05-23 10:56:33,936 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for cfb4d5cacedb5f6d21e332c533634338 with OFFLINE
> state
> 2011-05-23 10:56:33,936 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for 3e332c1a428fa51ade3ac3fbe5dfee50 with OFFLINE
> state
>
> -----邮件原件-----
> 发件人: Ted Yu [mailto:yuzhihong@gmail.com]
> 发送时间: 2011年5月26日 19:37
> 收件人: user@hbase.apache.org
> 主题: Re: About RegionServer checkin
>
> Do you see the following message in master log for 158-1-101-82 ?
>      String message = "Server " + what + " rejected; currently processing "
> +
>          serverName + " as dead server";
>
> Thanks
>
> On Thu, May 26, 2011 at 4:29 AM, Ted Yu <yu...@gmail.com> wrote:
>
> > This was from 158-1-101-82 log, right ?
> >
> > >> 2011-05-23 10:21:37,400 DEBUG org.apache.hadoop.hbase.
> > regionserver.handler.OpenRegionHandler: Opened
> > hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >
> > Can you paste more log before the above line ?
> > Master log around 2011-05-23 10:21:37,400 would help too.
> >
> >
> > On Thu, May 26, 2011 at 2:35 AM, Gaojinchao <ga...@huawei.com>
> wrote:
> >
> >> Sorry, I hate my poor English .
> >>
> >> I give a description again:
> >> Master add regionserver to onlineServers in two case:
> >> 1. Add a machine to the cluster, It includes cluster startup or add a
> new
> >> machine.
> >> Master can get region server information from api "regionServerStartup"
> >> and add to onlineServers set.
> >>
> >> 2. Master is restarted.
> >> Master can get region server information from api "regionServerReport"
> and
> >> add to onlineServers set.
> >> But It must be happened when Master called function
> >> waitForRegionServers().
> >> If region sever reported is later, Master will take it for a dead
> server.
> >> The regions will be assigned.
> >> So one region is opened in different region server.
> >>
> >> I think the later region server should shutdown itself and start again.
> It
> >> can register by api regionServerStartup
> >> But not api regionServerReport
> >>
> >> eg: region could not be assigned by balance
> >>
> >> Hmaster logs:
> >> 2011-05-23 11:12:10,588 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
> >> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to
> >> 158-1-101-82,20020,1306117051387
> >> 2011-05-23 11:15:20,472 INFO
> >> org.apache.hadoop.hbase.master.AssignmentManager: Regions in transition
> >> timed out:  hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> state=PENDING_OPEN, ts=1306120330588
> >> 2011-05-23 11:15:20,472 INFO
> >> org.apache.hadoop.hbase.master.AssignmentManager: Region has been
> >> PENDING_OPEN for too long, reassigning
> >> region=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:15:20,513 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: Forcing OFFLINE;
> >> was=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> state=PENDING_OPEN, ts=1306120330588
> >> 2011-05-23 11:15:20,513 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: No previous transition
> >> plan was found (or we are ignoring an existing plan) for
> >> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. so
> generated a
> >> random one;
> >> hri=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d., src=,
> >> dest=158-1-101-82,20020,1306117051387; 2 (online=2, exclude=null)
> available
> >> servers
> >> 2011-05-23 11:15:20,513 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
> >> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to
> >> 158-1-101-82,20020,1306117051387
> >> 2011-05-23 11:18:30,473 INFO
> >> org.apache.hadoop.hbase.master.AssignmentManager: Regions in transition
> >> timed out:  hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> state=PENDING_OPEN, ts=1306120520513
> >> 2011-05-23 11:18:30,473 INFO
> >> org.apache.hadoop.hbase.master.AssignmentManager: Region has been
> >> PENDING_OPEN for too long, reassigning
> >> region=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:18:30,487 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: Forcing OFFLINE;
> >> was=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> state=PENDING_OPEN, ts=1306120520513
> >> 2011-05-23 11:18:30,487 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: No previous transition
> >> plan was found (or we are ignoring an existing plan) for
> >> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. so
> generated a
> >> random one;
> >> hri=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d., src=,
> >> dest=158-1-101-222,20020,1306119315097; 2 (online=2, exclude=null)
> available
> >> servers
> >> 2011-05-23 11:18:30,488 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
> >> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to
> >> 158-1-101-222,20020,1306119315097
> >> 2011-05-23 11:18:30,516 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> >> transition=RS_ZK_REGION_OPENING,
> server=158-1-101-222,20020,1306119315097,
> >> region=70541f0abda274708e12570c52aa7f1d
> >> 2011-05-23 11:18:30,581 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> >> transition=RS_ZK_REGION_OPENING,
> server=158-1-101-222,20020,1306119315097,
> >> region=70541f0abda274708e12570c52aa7f1d
> >> 2011-05-23 11:18:30,900 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> >> transition=RS_ZK_REGION_OPENED,
> server=158-1-101-222,20020,1306119315097,
> >> region=70541f0abda274708e12570c52aa7f1d
> >> 2011-05-23 11:18:30,900 DEBUG
> >> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Handling
> OPENED
> >> event for 70541f0abda274708e12570c52aa7f1d; deleting unassigned node
> >> 2011-05-23 11:18:30,900 DEBUG
> org.apache.hadoop.hbase.zookeeper.ZKAssign:
> >> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006
> Deleting
> >> existing unassigned node for 70541f0abda274708e12570c52aa7f1d that is in
> >> expected state RS_ZK_REGION_OPENED
> >> 2011-05-23 11:18:30,930 DEBUG
> org.apache.hadoop.hbase.zookeeper.ZKAssign:
> >> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006
> >> Successfully deleted unassigned node for region
> >> 70541f0abda274708e12570c52aa7f1d in expected state RS_ZK_REGION_OPENED
> >>
> >>
> >> Regionserver logs:
> >> 2011-05-23 10:21:37,400 DEBUG
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Opened
> >> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:04:19,633 INFO
> >> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to
> open
> >> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:04:19,633 DEBUG
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
> Processing
> >> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:04:19,633 WARN
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
> Attempted
> >> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
> >> already online on this server
> >> 2011-05-23 11:09:00,615 INFO
> >> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to
> open
> >> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:09:00,615 DEBUG
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
> Processing
> >> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:09:00,615 WARN
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
> Attempted
> >> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
> >> already online on this server
> >> 2011-05-23 11:12:10,588 INFO
> >> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to
> open
> >> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:12:10,588 DEBUG
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
> Processing
> >> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:12:10,588 WARN
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
> Attempted
> >> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
> >> already online on this server
> >> 2011-05-23 11:15:20,513 INFO
> >> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to
> open
> >> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:15:20,513 DEBUG
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
> Processing
> >> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:15:20,513 WARN
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
> Attempted
> >> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
> >> already online on this server
> >>
> >
> >
>

Re: Hmaster is NullPointerException

Posted by Stack <st...@duboce.net>.
The below is hard to read but I think I follow you Gao.  Makes sense.
Do you have a patch?  (How did you manufacture the below?  Was it by
accident?  Its a good one).

St.Ack

On Fri, May 27, 2011 at 7:04 PM, Gaojinchao <ga...@huawei.com> wrote:
> issue:
> NullPointerException while hmaster starting.
>       java.lang.NullPointerException
>         at java.util.TreeMap.getEntry(TreeMap.java:324)
>         at java.util.TreeMap.get(TreeMap.java:255)
>         at org.apache.hadoop.hbase.master.AssignmentManager.addToServers(AssignmentManager.java:1512)
>         at org.apache.hadoop.hbase.master.AssignmentManager.regionOnline(AssignmentManager.java:606)
>         at org.apache.hadoop.hbase.master.AssignmentManager.processFailover(AssignmentManager.java:214)
>         at org.apache.hadoop.hbase.master.HMaster.finishInitialization(HMaster.java:402)
>         at org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:283)
>
> // below is my analysis
> private void finishInitialization()
> throws IOException, InterruptedException, KeeperException
> {
>
>    /*
>        In the function, waitForRegionServers return when some regionservers checkin.
>        The regionservers include some regions, but not root-region and meta-region.
>        (the Registered servers are 157-5-111-13, 157-5-111-14, 157-5-111-12)
>    */
>    int regionCount = his.serverManager.waitForRegionServers();
>
>    /*
>        In the function, we can know verifyRootRegionLocation/verifyMetaRegionLocation are succeed with the log of assigned=0,
>        and the root-regionserver and meta-regionserver are running.
>        (The 157-5-111-11 server is running, but not Registered. and server include root-region and meta-region.)
>    */
>    assignRootAndMeta();
>
>    if (regionCount == 0) {
>      LOG.info("Master startup proceeding: cluster startup");
>      this.assignmentManager.cleanoutUnassigned();
>      this.assignmentManager.assignAllUserRegions();
>    } else {
>      LOG.info("Master startup proceeding: master failover");
>
>      /*
>        HServerInfo hsi = this.serverManager.getHServerInfo(this.catalogTracker.getMetaLocation());
>        In processFailover function, call getHServerInfo return NULL pointer, hsi is NULL pointer.
>        Because the regionserver with meta-region has not Registered.
>      */
>      this.assignmentManager.processFailover();
>    }
> }
>
> the exception logs:
>
> 2011-05-21 14:44:47,973 INFO org.apache.hadoop.hbase.master.ServerManager: Waiting on regionserver(s) to checkin
> 2011-05-21 14:44:49,473 INFO org.apache.hadoop.hbase.master.ServerManager: Waiting on regionserver(s) to checkin
> 2011-05-21 14:44:50,974 INFO org.apache.hadoop.hbase.master.ServerManager: Waiting on regionserver(s) to checkin
> 2011-05-21 14:44:51,281 INFO org.apache.hadoop.hbase.master.ServerManager: Registering server=157-5-111-13,20020,1305877624933, regionCount=1543, userLoad=true
> 2011-05-21 14:44:51,722 INFO org.apache.hadoop.hbase.master.ServerManager: Registering server=157-5-111-14,20020,1305877627727, regionCount=1507, userLoad=true
> 2011-05-21 14:44:51,774 INFO org.apache.hadoop.hbase.master.ServerManager: Registering server=157-5-111-12,20020,1305877626108, regionCount=1521, userLoad=true
> 2011-05-21 14:44:52,474 INFO org.apache.hadoop.hbase.master.ServerManager: Waiting on regionserver(s) count to settle; currently=3
> 2011-05-21 14:44:53,974 INFO org.apache.hadoop.hbase.master.ServerManager: Finished waiting for regionserver count to settle; count=3, sleptFor=18000
> 2011-05-21 14:44:53,974 INFO org.apache.hadoop.hbase.master.ServerManager: Exiting wait on regionserver(s) to checkin; count=3, stopped=false, count of regions out on cluster=4571
> 2011-05-21 14:44:53,978 INFO org.apache.hadoop.hbase.master.MasterFileSystem: Log folder hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161 doesn't belong to a known region server, splitting
> 2011-05-21 14:44:53,991 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Splitting 2 hlog(s) in hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161
> 2011-05-21 14:44:53,992 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-0,5,main]: starting
> 2011-05-21 14:44:53,993 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-2,5,main]: starting
> 2011-05-21 14:44:53,993 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-3,5,main]: starting
> 2011-05-21 14:44:53,993 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-1,5,main]: starting
> 2011-05-21 14:44:53,993 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-6,5,main]: starting
> 2011-05-21 14:44:53,993 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-5,5,main]: starting
> 2011-05-21 14:44:53,993 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-4,5,main]: starting
> 2011-05-21 14:44:53,993 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-8,5,main]: starting
> 2011-05-21 14:44:53,993 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-7,5,main]: starting
> 2011-05-21 14:44:53,994 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-9,5,main]: starting
> 2011-05-21 14:44:53,994 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-11,5,main]: starting
> 2011-05-21 14:44:53,994 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-10,5,main]: starting
> 2011-05-21 14:44:53,994 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-12,5,main]: starting
> 2011-05-21 14:44:53,994 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-13,5,main]: starting
> 2011-05-21 14:44:53,994 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-14,5,main]: starting
> 2011-05-21 14:44:53,994 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-15,5,main]: starting
> 2011-05-21 14:44:53,994 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Splitting hlog 1 of 2: hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305875949857, length=1503902
> 2011-05-21 14:44:53,996 INFO org.apache.hadoop.hbase.util.FSUtils: Recovering file hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305875949857
> 2011-05-21 14:44:54,998 INFO org.apache.hadoop.hbase.util.FSUtils: Finished lease recover attempt for hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305875949857
> 2011-05-21 14:44:55,140 INFO org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogWriter: Using syncFs -- HDFS-200
> 2011-05-21 14:44:55,141 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Creating writer path=hdfs://157.5.111.10:9000/hbase/-ROOT-/70236052/recovered.edits/0000000000000021721 region=70236052
> 2011-05-21 14:44:55,177 INFO org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogWriter: Using syncFs -- HDFS-200
> 2011-05-21 14:44:55,177 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Creating writer path=hdfs://157.5.111.10:9000/hbase/.META./1028785192/recovered.edits/0000000000000021722 region=1028785192
> 2011-05-21 14:44:55,435 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Pushed=5400 entries from hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305875949857
> 2011-05-21 14:44:55,436 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Splitting hlog 2 of 2: hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305879556259, length=0
> 2011-05-21 14:44:55,436 INFO org.apache.hadoop.hbase.util.FSUtils: Recovering file hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305879556259
> 2011-05-21 14:44:56,439 INFO org.apache.hadoop.hbase.util.FSUtils: Finished lease recover attempt for hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305879556259
> 2011-05-21 14:44:56,439 WARN org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: File hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305879556259 might be still open, length is 0
> 2011-05-21 14:44:56,451 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Pushed=0 entries from hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305879556259
> 2011-05-21 14:44:56,489 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Archived processed log hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305875949857 to hdfs://157.5.111.10:9000/hbase/.oldlogs/157-5-111-11%3A20020.1305875949857
> 2011-05-21 14:44:56,506 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Archived processed log hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305879556259 to hdfs://157.5.111.10:9000/hbase/.oldlogs/157-5-111-11%3A20020.1305879556259
> 2011-05-21 14:44:56,523 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Waiting for split writer threads to finish
> 2011-05-21 14:44:57,438 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Split writers finished
> 2011-05-21 14:44:57,455 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Closed path hdfs://157.5.111.10:9000/hbase/.META./1028785192/recovered.edits/0000000000000021722 (wrote 5399 edits in 322ms)
> 2011-05-21 14:44:57,505 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Closed path hdfs://157.5.111.10:9000/hbase/-ROOT-/70236052/recovered.edits/0000000000000021721 (wrote 1 edits in 106ms)
> 2011-05-21 14:44:57,505 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: hlog file splitting completed in 3517 ms for hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161
> 2011-05-21 14:44:57,506 INFO org.apache.hadoop.hbase.master.MasterFileSystem: Log folder hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-12,20020,1305877626108 belongs to an existing region server
> 2011-05-21 14:44:57,506 INFO org.apache.hadoop.hbase.master.MasterFileSystem: Log folder hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-13,20020,1305877624933 belongs to an existing region server
> 2011-05-21 14:44:57,506 INFO org.apache.hadoop.hbase.master.MasterFileSystem: Log folder hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-14,20020,1305877627727 belongs to an existing region server
> 2011-05-21 14:44:57,524 INFO org.apache.hadoop.hbase.master.HMaster: -ROOT- assigned=0, rit=false, location=157-5-111-11:20020
> 2011-05-21 14:44:57,528 INFO org.apache.hadoop.hbase.master.HMaster: .META. assigned=0, rit=false, location=157-5-111-11:20020
> 2011-05-21 14:44:57,528 INFO org.apache.hadoop.hbase.master.HMaster: Master startup proceeding: master failover
> 2011-05-21 14:44:57,530 FATAL org.apache.hadoop.hbase.master.HMaster: Unhandled exception. Starting shutdown.
> java.lang.NullPointerException
>         at java.util.TreeMap.getEntry(TreeMap.java:324)
>         at java.util.TreeMap.get(TreeMap.java:255)
>         at org.apache.hadoop.hbase.master.AssignmentManager.addToServers(AssignmentManager.java:1512)
>         at org.apache.hadoop.hbase.master.AssignmentManager.regionOnline(AssignmentManager.java:606)
>         at org.apache.hadoop.hbase.master.AssignmentManager.processFailover(AssignmentManager.java:214)
>         at org.apache.hadoop.hbase.master.HMaster.finishInitialization(HMaster.java:402)
>         at org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:283)
> 2011-05-21 14:44:57,531 INFO org.apache.hadoop.hbase.master.HMaster: Aborting
> 2011-05-21 14:44:57,531 DEBUG org.apache.hadoop.hbase.master.HMaster: Stopping service threads
>

Hmaster is NullPointerException

Posted by Gaojinchao <ga...@huawei.com>.
issue:
NullPointerException while hmaster starting.
       java.lang.NullPointerException
         at java.util.TreeMap.getEntry(TreeMap.java:324)
         at java.util.TreeMap.get(TreeMap.java:255)
         at org.apache.hadoop.hbase.master.AssignmentManager.addToServers(AssignmentManager.java:1512)
         at org.apache.hadoop.hbase.master.AssignmentManager.regionOnline(AssignmentManager.java:606)
         at org.apache.hadoop.hbase.master.AssignmentManager.processFailover(AssignmentManager.java:214)
         at org.apache.hadoop.hbase.master.HMaster.finishInitialization(HMaster.java:402)
         at org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:283)

// below is my analysis
private void finishInitialization()
throws IOException, InterruptedException, KeeperException
{

    /*
        In the function, waitForRegionServers return when some regionservers checkin.
        The regionservers include some regions, but not root-region and meta-region.
        (the Registered servers are 157-5-111-13, 157-5-111-14, 157-5-111-12)
    */
    int regionCount = his.serverManager.waitForRegionServers();

    /*
        In the function, we can know verifyRootRegionLocation/verifyMetaRegionLocation are succeed with the log of assigned=0,
        and the root-regionserver and meta-regionserver are running.
        (The 157-5-111-11 server is running, but not Registered. and server include root-region and meta-region.)
    */
    assignRootAndMeta();

    if (regionCount == 0) {
      LOG.info("Master startup proceeding: cluster startup");
      this.assignmentManager.cleanoutUnassigned();
      this.assignmentManager.assignAllUserRegions();
    } else {
      LOG.info("Master startup proceeding: master failover");

      /*
        HServerInfo hsi = this.serverManager.getHServerInfo(this.catalogTracker.getMetaLocation());
        In processFailover function, call getHServerInfo return NULL pointer, hsi is NULL pointer.
        Because the regionserver with meta-region has not Registered.
      */
      this.assignmentManager.processFailover();
    }
}

the exception logs:

2011-05-21 14:44:47,973 INFO org.apache.hadoop.hbase.master.ServerManager: Waiting on regionserver(s) to checkin
2011-05-21 14:44:49,473 INFO org.apache.hadoop.hbase.master.ServerManager: Waiting on regionserver(s) to checkin
2011-05-21 14:44:50,974 INFO org.apache.hadoop.hbase.master.ServerManager: Waiting on regionserver(s) to checkin
2011-05-21 14:44:51,281 INFO org.apache.hadoop.hbase.master.ServerManager: Registering server=157-5-111-13,20020,1305877624933, regionCount=1543, userLoad=true
2011-05-21 14:44:51,722 INFO org.apache.hadoop.hbase.master.ServerManager: Registering server=157-5-111-14,20020,1305877627727, regionCount=1507, userLoad=true
2011-05-21 14:44:51,774 INFO org.apache.hadoop.hbase.master.ServerManager: Registering server=157-5-111-12,20020,1305877626108, regionCount=1521, userLoad=true
2011-05-21 14:44:52,474 INFO org.apache.hadoop.hbase.master.ServerManager: Waiting on regionserver(s) count to settle; currently=3
2011-05-21 14:44:53,974 INFO org.apache.hadoop.hbase.master.ServerManager: Finished waiting for regionserver count to settle; count=3, sleptFor=18000
2011-05-21 14:44:53,974 INFO org.apache.hadoop.hbase.master.ServerManager: Exiting wait on regionserver(s) to checkin; count=3, stopped=false, count of regions out on cluster=4571
2011-05-21 14:44:53,978 INFO org.apache.hadoop.hbase.master.MasterFileSystem: Log folder hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161 doesn't belong to a known region server, splitting
2011-05-21 14:44:53,991 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Splitting 2 hlog(s) in hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161
2011-05-21 14:44:53,992 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-0,5,main]: starting
2011-05-21 14:44:53,993 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-2,5,main]: starting
2011-05-21 14:44:53,993 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-3,5,main]: starting
2011-05-21 14:44:53,993 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-1,5,main]: starting
2011-05-21 14:44:53,993 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-6,5,main]: starting
2011-05-21 14:44:53,993 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-5,5,main]: starting
2011-05-21 14:44:53,993 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-4,5,main]: starting
2011-05-21 14:44:53,993 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-8,5,main]: starting
2011-05-21 14:44:53,993 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-7,5,main]: starting
2011-05-21 14:44:53,994 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-9,5,main]: starting
2011-05-21 14:44:53,994 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-11,5,main]: starting
2011-05-21 14:44:53,994 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-10,5,main]: starting
2011-05-21 14:44:53,994 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-12,5,main]: starting
2011-05-21 14:44:53,994 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-13,5,main]: starting
2011-05-21 14:44:53,994 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-14,5,main]: starting
2011-05-21 14:44:53,994 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-15,5,main]: starting
2011-05-21 14:44:53,994 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Splitting hlog 1 of 2: hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305875949857, length=1503902
2011-05-21 14:44:53,996 INFO org.apache.hadoop.hbase.util.FSUtils: Recovering file hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305875949857
2011-05-21 14:44:54,998 INFO org.apache.hadoop.hbase.util.FSUtils: Finished lease recover attempt for hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305875949857
2011-05-21 14:44:55,140 INFO org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogWriter: Using syncFs -- HDFS-200
2011-05-21 14:44:55,141 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Creating writer path=hdfs://157.5.111.10:9000/hbase/-ROOT-/70236052/recovered.edits/0000000000000021721 region=70236052
2011-05-21 14:44:55,177 INFO org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogWriter: Using syncFs -- HDFS-200
2011-05-21 14:44:55,177 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Creating writer path=hdfs://157.5.111.10:9000/hbase/.META./1028785192/recovered.edits/0000000000000021722 region=1028785192
2011-05-21 14:44:55,435 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Pushed=5400 entries from hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305875949857
2011-05-21 14:44:55,436 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Splitting hlog 2 of 2: hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305879556259, length=0
2011-05-21 14:44:55,436 INFO org.apache.hadoop.hbase.util.FSUtils: Recovering file hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305879556259
2011-05-21 14:44:56,439 INFO org.apache.hadoop.hbase.util.FSUtils: Finished lease recover attempt for hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305879556259
2011-05-21 14:44:56,439 WARN org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: File hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305879556259 might be still open, length is 0
2011-05-21 14:44:56,451 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Pushed=0 entries from hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305879556259
2011-05-21 14:44:56,489 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Archived processed log hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305875949857 to hdfs://157.5.111.10:9000/hbase/.oldlogs/157-5-111-11%3A20020.1305875949857
2011-05-21 14:44:56,506 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Archived processed log hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161/157-5-111-11%3A20020.1305879556259 to hdfs://157.5.111.10:9000/hbase/.oldlogs/157-5-111-11%3A20020.1305879556259
2011-05-21 14:44:56,523 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Waiting for split writer threads to finish
2011-05-21 14:44:57,438 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Split writers finished
2011-05-21 14:44:57,455 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Closed path hdfs://157.5.111.10:9000/hbase/.META./1028785192/recovered.edits/0000000000000021722 (wrote 5399 edits in 322ms)
2011-05-21 14:44:57,505 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Closed path hdfs://157.5.111.10:9000/hbase/-ROOT-/70236052/recovered.edits/0000000000000021721 (wrote 1 edits in 106ms)
2011-05-21 14:44:57,505 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: hlog file splitting completed in 3517 ms for hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-11,20020,1305875930161
2011-05-21 14:44:57,506 INFO org.apache.hadoop.hbase.master.MasterFileSystem: Log folder hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-12,20020,1305877626108 belongs to an existing region server
2011-05-21 14:44:57,506 INFO org.apache.hadoop.hbase.master.MasterFileSystem: Log folder hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-13,20020,1305877624933 belongs to an existing region server
2011-05-21 14:44:57,506 INFO org.apache.hadoop.hbase.master.MasterFileSystem: Log folder hdfs://157.5.111.10:9000/hbase/.logs/157-5-111-14,20020,1305877627727 belongs to an existing region server
2011-05-21 14:44:57,524 INFO org.apache.hadoop.hbase.master.HMaster: -ROOT- assigned=0, rit=false, location=157-5-111-11:20020
2011-05-21 14:44:57,528 INFO org.apache.hadoop.hbase.master.HMaster: .META. assigned=0, rit=false, location=157-5-111-11:20020
2011-05-21 14:44:57,528 INFO org.apache.hadoop.hbase.master.HMaster: Master startup proceeding: master failover
2011-05-21 14:44:57,530 FATAL org.apache.hadoop.hbase.master.HMaster: Unhandled exception. Starting shutdown.
java.lang.NullPointerException
         at java.util.TreeMap.getEntry(TreeMap.java:324)
         at java.util.TreeMap.get(TreeMap.java:255)
         at org.apache.hadoop.hbase.master.AssignmentManager.addToServers(AssignmentManager.java:1512)
         at org.apache.hadoop.hbase.master.AssignmentManager.regionOnline(AssignmentManager.java:606)
         at org.apache.hadoop.hbase.master.AssignmentManager.processFailover(AssignmentManager.java:214)
         at org.apache.hadoop.hbase.master.HMaster.finishInitialization(HMaster.java:402)
         at org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:283)
2011-05-21 14:44:57,531 INFO org.apache.hadoop.hbase.master.HMaster: Aborting
2011-05-21 14:44:57,531 DEBUG org.apache.hadoop.hbase.master.HMaster: Stopping service threads

Re: About RegionServer checkin

Posted by Ted Yu <yu...@gmail.com>.
>> 2011-05-23 10:56:33,504 INFO
org.apache.hadoop.hbase.master.ServerManager: Registering
server=158-1-101-82,20020,1306117051387, regionCount=1344, userLoad=true

For the above log, ServerManager would execute this in recordNewServer():
    LOG.info("Registering server=" + serverName);
    this.onlineServers.put(serverName, hsl);
It was called by regionServerReport().

2011/5/26 Gaojinchao <ga...@huawei.com>

> Thanks for your reply. I understand your mean.
> But It is not enough.
> This is log.
>
> Hmaster log:
> 2011-05-23 10:56:17,326 INFO org.apache.hadoop.hbase.master.ServerManager:
> Waiting on regionserver(s) to checkin
> 2011-05-23 10:56:18,393 INFO org.apache.hadoop.hbase.master.ServerManager:
> Registering server=158-1-101-222,20020,1306119315097, regionCount=0,
> userLoad=false
> 2011-05-23 10:56:18,826 INFO org.apache.hadoop.hbase.master.ServerManager:
> Waiting on regionserver(s) count to settle; currently=1
> 2011-05-23 10:56:20,326 INFO org.apache.hadoop.hbase.master.ServerManager:
> Finished waiting for regionserver count to settle; count=1, sleptFor=19500
> 2011-05-23 10:56:20,326 INFO org.apache.hadoop.hbase.master.ServerManager:
> Exiting wait on regionserver(s) to checkin; count=1, stopped=false, count of
> regions out on cluster=0
> 2011-05-23 10:56:20,329 INFO
> org.apache.hadoop.hbase.master.MasterFileSystem: Log folder hdfs://
> 158.1.101.82:9000/hbase/.logs/158-1-101-222,20020,1306111562081 doesn't
> belong to a known region server, splitting
> 2011-05-23 10:56:20,341 INFO
> org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Splitting 2 hlog(s)
> in hdfs://158.1.101.82:9000/hbase/.logs/158-1-101-222,20020,1306111562081
> 2011-05-23<http://158.1.101.82:9000/hbase/.logs/158-1-101-222,20020,1306111562081%0A2011-05-23>10:56:20,342 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter:
> Writer thread Thread[WriterThread-0,5,main]: starting
> .......
> 2011-05-23 10:56:25,152 INFO
> org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Waiting for split
> writer threads to finish
> 2011-05-23 10:56:25,983 INFO
> org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Split writers
> finished
> 2011-05-23 10:56:25,983 INFO
> org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: hlog file splitting
> completed in 2004 ms for hdfs://
> 158.1.101.82:9000/hbase/.logs/158-1-101-82,20020,1306117051387
> 2011-05-23<http://158.1.101.82:9000/hbase/.logs/158-1-101-82,20020,1306117051387%0A2011-05-23>10:56:29,032 WARN
> org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation:
> RemoteException connecting to RS
> org.apache.hadoop.ipc.RemoteException:
> org.apache.hadoop.hbase.ipc.ServerNotRunningException: Server is not running
> yet
>        at
> org.apache.hadoop.hbase.master.HMaster.assignRootAndMeta(HMaster.java:431)
>        at
> org.apache.hadoop.hbase.master.HMaster.finishInitialization(HMaster.java:389)
>        at org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:283)
> 2011-05-23 10:56:29,034 INFO
> org.apache.hadoop.hbase.catalog.RootLocationEditor: Unsetting ROOT region
> location in ZooKeeper
> 2011-05-23 10:56:29,058 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Creating
> (or updating) unassigned node for 70236052 with OFFLINE state
> 2011-05-23 10:56:29,071 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: 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=158-1-101-222,20020,1306119315097; 1 (online=1, exclude=null) available
> servers
> 2011-05-23 10:56:29,071 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
> -ROOT-,,0.70236052 to 158-1-101-222,20020,1306119315097
> 2011-05-23 10:56:29,071 DEBUG org.apache.hadoop.hbase.master.ServerManager:
> New connection to 158-1-101-222,20020,1306119315097
> 2011-05-23 10:56:29,095 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097,
> region=70236052/-ROOT-
> 2011-05-23 10:56:29,208 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097,
> region=70236052/-ROOT-
> 2011-05-23 10:56:29,220 INFO org.apache.hadoop.hbase.master.HMaster: -ROOT-
> assigned=1, rit=false, location=158-1-101-222:20020
> 2011-05-23 10:56:29,233 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> transition=RS_ZK_REGION_OPENED, server=158-1-101-222,20020,1306119315097,
> region=70236052/-ROOT-
> 2011-05-23 10:56:29,236 DEBUG
> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Handling OPENED
> event for 70236052; deleting unassigned node
> 2011-05-23 10:56:29,236 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Deleting
> existing unassigned node for 70236052 that is in expected state
> RS_ZK_REGION_OPENED
> 2011-05-23 10:56:29,245 INFO
> org.apache.hadoop.hbase.catalog.CatalogTracker: Failed verification of
> .META.,,1 at address=null;
> org.apache.hadoop.hbase.NotServingRegionException:
> org.apache.hadoop.hbase.NotServingRegionException: Region is not online:
> .META.,,1
> 2011-05-23 10:56:29,245 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Creating
> (or updating) unassigned node for 1028785192 with OFFLINE state
> 2011-05-23 10:56:29,252 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006
> Successfully deleted unassigned node for region 70236052 in expected state
> RS_ZK_REGION_OPENED
> 2011-05-23 10:56:29,254 DEBUG
> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Opened region
> -ROOT-,,0.70236052 on 158-1-101-222,20020,1306119315097
> 2011-05-23 10:56:29,263 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> transition=M_ZK_REGION_OFFLINE, server=158-1-101-222:20000,
> region=1028785192/.META.
> 2011-05-23 10:56:29,263 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: 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=158-1-101-222,20020,1306119315097; 1 (online=1, exclude=null)
> available servers
> 2011-05-23 10:56:29,263 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
> .META.,,1.1028785192 to 158-1-101-222,20020,1306119315097
> 2011-05-23 10:56:29,278 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097,
> region=1028785192/.META.
> 2011-05-23 10:56:30,682 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097,
> region=1028785192/.META.
> 2011-05-23 10:56:30,711 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> transition=RS_ZK_REGION_OPENED, server=158-1-101-222,20020,1306119315097,
> region=1028785192/.META.
> 2011-05-23 10:56:30,712 DEBUG
> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Handling OPENED
> event for 1028785192; deleting unassigned node
> 2011-05-23 10:56:30,712 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Deleting
> existing unassigned node for 1028785192 that is in expected state
> RS_ZK_REGION_OPENED
> 2011-05-23 10:56:30,719 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006
> Successfully deleted unassigned node for region 1028785192 in expected state
> RS_ZK_REGION_OPENED
> 2011-05-23 10:56:30,719 DEBUG
> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Opened region
> .META.,,1.1028785192 on 158-1-101-222,20020,1306119315097
> 2011-05-23 10:56:30,719 INFO
> org.apache.hadoop.hbase.zookeeper.MetaNodeTracker: Detected completed
> assignment of META, notifying catalog tracker
> 2011-05-23 10:56:30,726 INFO org.apache.hadoop.hbase.master.HMaster: .META.
> assigned=2, rit=false, location=158-1-101-222:20020
> 2011-05-23 10:56:30,726 INFO org.apache.hadoop.hbase.master.HMaster: Master
> startup proceeding: cluster startup
> 2011-05-23 10:56:30,726 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Deleting
> any existing unassigned nodes
>
> // regionserver(158-1-101-82) Registered
> 2011-05-23 10:56:33,504 INFO org.apache.hadoop.hbase.master.ServerManager:
> Registering server=158-1-101-82,20020,1306117051387, regionCount=1344,
> userLoad=true
> 2011-05-23 10:56:33,875 INFO
> org.apache.hadoop.hbase.master.AssignmentManager: Bulk assigning 5041
> region(s) across 1 server(s), retainAssignment=true
> 2011-05-23 10:56:33,876 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Timeout-on-RIT=5041000
>
> //regions was opened in 158-1-101-222 machine
> 2011-05-23 10:56:33,876 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Bulk assigning 5041
> region(s) to 158-1-101-222,20020,1306119315097
> 2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for b18eba004dfe6b1224f16a275ec342d1 with OFFLINE
> state
> 2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for 43b4b419baec6114a9afbc1432d17856 with OFFLINE
> state
> 2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for 17eb7fc069d11de1d403499caff024e4 with OFFLINE
> state
> 2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for ef4ec24ce49e31ec2c5c51a4acc76e4e with OFFLINE
> state
> 2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for 86e6193a18c887a2ebcaf7c409ac7c5f with OFFLINE
> state
> 2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for 5f81b6cecf483f0f8b26fce5b7040078 with OFFLINE
> state
> 2011-05-23 10:56:33,936 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for faf9d38383ac7d8d594743e8aee400e3 with OFFLINE
> state
> 2011-05-23 10:56:33,936 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for 52a547b878ca41dc1a6fbf84800bf1c3 with OFFLINE
> state
> 2011-05-23 10:56:33,936 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for cfb4d5cacedb5f6d21e332c533634338 with OFFLINE
> state
> 2011-05-23 10:56:33,936 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async
> create of unassigned node for 3e332c1a428fa51ade3ac3fbe5dfee50 with OFFLINE
> state
>
> -----邮件原件-----
> 发件人: Ted Yu [mailto:yuzhihong@gmail.com]
> 发送时间: 2011年5月26日 19:37
> 收件人: user@hbase.apache.org
> 主题: Re: About RegionServer checkin
>
> Do you see the following message in master log for 158-1-101-82 ?
>      String message = "Server " + what + " rejected; currently processing "
> +
>          serverName + " as dead server";
>
> Thanks
>
> On Thu, May 26, 2011 at 4:29 AM, Ted Yu <yu...@gmail.com> wrote:
>
> > This was from 158-1-101-82 log, right ?
> >
> > >> 2011-05-23 10:21:37,400 DEBUG org.apache.hadoop.hbase.
> > regionserver.handler.OpenRegionHandler: Opened
> > hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >
> > Can you paste more log before the above line ?
> > Master log around 2011-05-23 10:21:37,400 would help too.
> >
> >
> > On Thu, May 26, 2011 at 2:35 AM, Gaojinchao <ga...@huawei.com>
> wrote:
> >
> >> Sorry, I hate my poor English .
> >>
> >> I give a description again:
> >> Master add regionserver to onlineServers in two case:
> >> 1. Add a machine to the cluster, It includes cluster startup or add a
> new
> >> machine.
> >> Master can get region server information from api "regionServerStartup"
> >> and add to onlineServers set.
> >>
> >> 2. Master is restarted.
> >> Master can get region server information from api "regionServerReport"
> and
> >> add to onlineServers set.
> >> But It must be happened when Master called function
> >> waitForRegionServers().
> >> If region sever reported is later, Master will take it for a dead
> server.
> >> The regions will be assigned.
> >> So one region is opened in different region server.
> >>
> >> I think the later region server should shutdown itself and start again.
> It
> >> can register by api regionServerStartup
> >> But not api regionServerReport
> >>
> >> eg: region could not be assigned by balance
> >>
> >> Hmaster logs:
> >> 2011-05-23 11:12:10,588 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
> >> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to
> >> 158-1-101-82,20020,1306117051387
> >> 2011-05-23 11:15:20,472 INFO
> >> org.apache.hadoop.hbase.master.AssignmentManager: Regions in transition
> >> timed out:  hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> state=PENDING_OPEN, ts=1306120330588
> >> 2011-05-23 11:15:20,472 INFO
> >> org.apache.hadoop.hbase.master.AssignmentManager: Region has been
> >> PENDING_OPEN for too long, reassigning
> >> region=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:15:20,513 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: Forcing OFFLINE;
> >> was=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> state=PENDING_OPEN, ts=1306120330588
> >> 2011-05-23 11:15:20,513 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: No previous transition
> >> plan was found (or we are ignoring an existing plan) for
> >> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. so
> generated a
> >> random one;
> >> hri=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d., src=,
> >> dest=158-1-101-82,20020,1306117051387; 2 (online=2, exclude=null)
> available
> >> servers
> >> 2011-05-23 11:15:20,513 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
> >> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to
> >> 158-1-101-82,20020,1306117051387
> >> 2011-05-23 11:18:30,473 INFO
> >> org.apache.hadoop.hbase.master.AssignmentManager: Regions in transition
> >> timed out:  hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> state=PENDING_OPEN, ts=1306120520513
> >> 2011-05-23 11:18:30,473 INFO
> >> org.apache.hadoop.hbase.master.AssignmentManager: Region has been
> >> PENDING_OPEN for too long, reassigning
> >> region=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:18:30,487 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: Forcing OFFLINE;
> >> was=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> state=PENDING_OPEN, ts=1306120520513
> >> 2011-05-23 11:18:30,487 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: No previous transition
> >> plan was found (or we are ignoring an existing plan) for
> >> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. so
> generated a
> >> random one;
> >> hri=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d., src=,
> >> dest=158-1-101-222,20020,1306119315097; 2 (online=2, exclude=null)
> available
> >> servers
> >> 2011-05-23 11:18:30,488 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
> >> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to
> >> 158-1-101-222,20020,1306119315097
> >> 2011-05-23 11:18:30,516 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> >> transition=RS_ZK_REGION_OPENING,
> server=158-1-101-222,20020,1306119315097,
> >> region=70541f0abda274708e12570c52aa7f1d
> >> 2011-05-23 11:18:30,581 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> >> transition=RS_ZK_REGION_OPENING,
> server=158-1-101-222,20020,1306119315097,
> >> region=70541f0abda274708e12570c52aa7f1d
> >> 2011-05-23 11:18:30,900 DEBUG
> >> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> >> transition=RS_ZK_REGION_OPENED,
> server=158-1-101-222,20020,1306119315097,
> >> region=70541f0abda274708e12570c52aa7f1d
> >> 2011-05-23 11:18:30,900 DEBUG
> >> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Handling
> OPENED
> >> event for 70541f0abda274708e12570c52aa7f1d; deleting unassigned node
> >> 2011-05-23 11:18:30,900 DEBUG
> org.apache.hadoop.hbase.zookeeper.ZKAssign:
> >> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006
> Deleting
> >> existing unassigned node for 70541f0abda274708e12570c52aa7f1d that is in
> >> expected state RS_ZK_REGION_OPENED
> >> 2011-05-23 11:18:30,930 DEBUG
> org.apache.hadoop.hbase.zookeeper.ZKAssign:
> >> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006
> >> Successfully deleted unassigned node for region
> >> 70541f0abda274708e12570c52aa7f1d in expected state RS_ZK_REGION_OPENED
> >>
> >>
> >> Regionserver logs:
> >> 2011-05-23 10:21:37,400 DEBUG
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Opened
> >> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:04:19,633 INFO
> >> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to
> open
> >> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:04:19,633 DEBUG
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
> Processing
> >> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:04:19,633 WARN
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
> Attempted
> >> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
> >> already online on this server
> >> 2011-05-23 11:09:00,615 INFO
> >> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to
> open
> >> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:09:00,615 DEBUG
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
> Processing
> >> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:09:00,615 WARN
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
> Attempted
> >> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
> >> already online on this server
> >> 2011-05-23 11:12:10,588 INFO
> >> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to
> open
> >> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:12:10,588 DEBUG
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
> Processing
> >> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:12:10,588 WARN
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
> Attempted
> >> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
> >> already online on this server
> >> 2011-05-23 11:15:20,513 INFO
> >> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to
> open
> >> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:15:20,513 DEBUG
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
> Processing
> >> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> >> 2011-05-23 11:15:20,513 WARN
> >> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
> Attempted
> >> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
> >> already online on this server
> >>
> >
> >
>

Re: About RegionServer checkin

Posted by Gaojinchao <ga...@huawei.com>.
Thanks for your reply. I understand your mean.
But It is not enough. 
This is log.

Hmaster log:
2011-05-23 10:56:17,326 INFO org.apache.hadoop.hbase.master.ServerManager: Waiting on regionserver(s) to checkin
2011-05-23 10:56:18,393 INFO org.apache.hadoop.hbase.master.ServerManager: Registering server=158-1-101-222,20020,1306119315097, regionCount=0, userLoad=false
2011-05-23 10:56:18,826 INFO org.apache.hadoop.hbase.master.ServerManager: Waiting on regionserver(s) count to settle; currently=1
2011-05-23 10:56:20,326 INFO org.apache.hadoop.hbase.master.ServerManager: Finished waiting for regionserver count to settle; count=1, sleptFor=19500
2011-05-23 10:56:20,326 INFO org.apache.hadoop.hbase.master.ServerManager: Exiting wait on regionserver(s) to checkin; count=1, stopped=false, count of regions out on cluster=0
2011-05-23 10:56:20,329 INFO org.apache.hadoop.hbase.master.MasterFileSystem: Log folder hdfs://158.1.101.82:9000/hbase/.logs/158-1-101-222,20020,1306111562081 doesn't belong to a known region server, splitting
2011-05-23 10:56:20,341 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Splitting 2 hlog(s) in hdfs://158.1.101.82:9000/hbase/.logs/158-1-101-222,20020,1306111562081
2011-05-23 10:56:20,342 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Writer thread Thread[WriterThread-0,5,main]: starting
.......
2011-05-23 10:56:25,152 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Waiting for split writer threads to finish
2011-05-23 10:56:25,983 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: Split writers finished
2011-05-23 10:56:25,983 INFO org.apache.hadoop.hbase.regionserver.wal.HLogSplitter: hlog file splitting completed in 2004 ms for hdfs://158.1.101.82:9000/hbase/.logs/158-1-101-82,20020,1306117051387
2011-05-23 10:56:29,032 WARN org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation: RemoteException connecting to RS
org.apache.hadoop.ipc.RemoteException: org.apache.hadoop.hbase.ipc.ServerNotRunningException: Server is not running yet
	at org.apache.hadoop.hbase.master.HMaster.assignRootAndMeta(HMaster.java:431)
	at org.apache.hadoop.hbase.master.HMaster.finishInitialization(HMaster.java:389)
	at org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:283)
2011-05-23 10:56:29,034 INFO org.apache.hadoop.hbase.catalog.RootLocationEditor: Unsetting ROOT region location in ZooKeeper
2011-05-23 10:56:29,058 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Creating (or updating) unassigned node for 70236052 with OFFLINE state
2011-05-23 10:56:29,071 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: 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=158-1-101-222,20020,1306119315097; 1 (online=1, exclude=null) available servers
2011-05-23 10:56:29,071 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Assigning region -ROOT-,,0.70236052 to 158-1-101-222,20020,1306119315097
2011-05-23 10:56:29,071 DEBUG org.apache.hadoop.hbase.master.ServerManager: New connection to 158-1-101-222,20020,1306119315097
2011-05-23 10:56:29,095 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Handling transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097, region=70236052/-ROOT-
2011-05-23 10:56:29,208 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Handling transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097, region=70236052/-ROOT-
2011-05-23 10:56:29,220 INFO org.apache.hadoop.hbase.master.HMaster: -ROOT- assigned=1, rit=false, location=158-1-101-222:20020
2011-05-23 10:56:29,233 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Handling transition=RS_ZK_REGION_OPENED, server=158-1-101-222,20020,1306119315097, region=70236052/-ROOT-
2011-05-23 10:56:29,236 DEBUG org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Handling OPENED event for 70236052; deleting unassigned node
2011-05-23 10:56:29,236 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Deleting existing unassigned node for 70236052 that is in expected state RS_ZK_REGION_OPENED
2011-05-23 10:56:29,245 INFO org.apache.hadoop.hbase.catalog.CatalogTracker: Failed verification of .META.,,1 at address=null; org.apache.hadoop.hbase.NotServingRegionException: org.apache.hadoop.hbase.NotServingRegionException: Region is not online: .META.,,1
2011-05-23 10:56:29,245 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Creating (or updating) unassigned node for 1028785192 with OFFLINE state
2011-05-23 10:56:29,252 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Successfully deleted unassigned node for region 70236052 in expected state RS_ZK_REGION_OPENED
2011-05-23 10:56:29,254 DEBUG org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Opened region -ROOT-,,0.70236052 on 158-1-101-222,20020,1306119315097
2011-05-23 10:56:29,263 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Handling transition=M_ZK_REGION_OFFLINE, server=158-1-101-222:20000, region=1028785192/.META.
2011-05-23 10:56:29,263 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: 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=158-1-101-222,20020,1306119315097; 1 (online=1, exclude=null) available servers
2011-05-23 10:56:29,263 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Assigning region .META.,,1.1028785192 to 158-1-101-222,20020,1306119315097
2011-05-23 10:56:29,278 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Handling transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097, region=1028785192/.META.
2011-05-23 10:56:30,682 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Handling transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097, region=1028785192/.META.
2011-05-23 10:56:30,711 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Handling transition=RS_ZK_REGION_OPENED, server=158-1-101-222,20020,1306119315097, region=1028785192/.META.
2011-05-23 10:56:30,712 DEBUG org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Handling OPENED event for 1028785192; deleting unassigned node
2011-05-23 10:56:30,712 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Deleting existing unassigned node for 1028785192 that is in expected state RS_ZK_REGION_OPENED
2011-05-23 10:56:30,719 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Successfully deleted unassigned node for region 1028785192 in expected state RS_ZK_REGION_OPENED
2011-05-23 10:56:30,719 DEBUG org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Opened region .META.,,1.1028785192 on 158-1-101-222,20020,1306119315097
2011-05-23 10:56:30,719 INFO org.apache.hadoop.hbase.zookeeper.MetaNodeTracker: Detected completed assignment of META, notifying catalog tracker
2011-05-23 10:56:30,726 INFO org.apache.hadoop.hbase.master.HMaster: .META. assigned=2, rit=false, location=158-1-101-222:20020
2011-05-23 10:56:30,726 INFO org.apache.hadoop.hbase.master.HMaster: Master startup proceeding: cluster startup
2011-05-23 10:56:30,726 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Deleting any existing unassigned nodes

// regionserver(158-1-101-82) Registered 
2011-05-23 10:56:33,504 INFO org.apache.hadoop.hbase.master.ServerManager: Registering server=158-1-101-82,20020,1306117051387, regionCount=1344, userLoad=true
2011-05-23 10:56:33,875 INFO org.apache.hadoop.hbase.master.AssignmentManager: Bulk assigning 5041 region(s) across 1 server(s), retainAssignment=true
2011-05-23 10:56:33,876 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Timeout-on-RIT=5041000

//regions was opened in 158-1-101-222 machine
2011-05-23 10:56:33,876 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Bulk assigning 5041 region(s) to 158-1-101-222,20020,1306119315097
2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async create of unassigned node for b18eba004dfe6b1224f16a275ec342d1 with OFFLINE state
2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async create of unassigned node for 43b4b419baec6114a9afbc1432d17856 with OFFLINE state
2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async create of unassigned node for 17eb7fc069d11de1d403499caff024e4 with OFFLINE state
2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async create of unassigned node for ef4ec24ce49e31ec2c5c51a4acc76e4e with OFFLINE state
2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async create of unassigned node for 86e6193a18c887a2ebcaf7c409ac7c5f with OFFLINE state
2011-05-23 10:56:33,935 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async create of unassigned node for 5f81b6cecf483f0f8b26fce5b7040078 with OFFLINE state
2011-05-23 10:56:33,936 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async create of unassigned node for faf9d38383ac7d8d594743e8aee400e3 with OFFLINE state
2011-05-23 10:56:33,936 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async create of unassigned node for 52a547b878ca41dc1a6fbf84800bf1c3 with OFFLINE state
2011-05-23 10:56:33,936 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async create of unassigned node for cfb4d5cacedb5f6d21e332c533634338 with OFFLINE state
2011-05-23 10:56:33,936 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Async create of unassigned node for 3e332c1a428fa51ade3ac3fbe5dfee50 with OFFLINE state

-----邮件原件-----
发件人: Ted Yu [mailto:yuzhihong@gmail.com] 
发送时间: 2011年5月26日 19:37
收件人: user@hbase.apache.org
主题: Re: About RegionServer checkin

Do you see the following message in master log for 158-1-101-82 ?
      String message = "Server " + what + " rejected; currently processing "
+
          serverName + " as dead server";

Thanks

On Thu, May 26, 2011 at 4:29 AM, Ted Yu <yu...@gmail.com> wrote:

> This was from 158-1-101-82 log, right ?
>
> >> 2011-05-23 10:21:37,400 DEBUG org.apache.hadoop.hbase.
> regionserver.handler.OpenRegionHandler: Opened
> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>
> Can you paste more log before the above line ?
> Master log around 2011-05-23 10:21:37,400 would help too.
>
>
> On Thu, May 26, 2011 at 2:35 AM, Gaojinchao <ga...@huawei.com> wrote:
>
>> Sorry, I hate my poor English .
>>
>> I give a description again:
>> Master add regionserver to onlineServers in two case:
>> 1. Add a machine to the cluster, It includes cluster startup or add a new
>> machine.
>> Master can get region server information from api "regionServerStartup"
>> and add to onlineServers set.
>>
>> 2. Master is restarted.
>> Master can get region server information from api "regionServerReport" and
>> add to onlineServers set.
>> But It must be happened when Master called function
>> waitForRegionServers().
>> If region sever reported is later, Master will take it for a dead server.
>> The regions will be assigned.
>> So one region is opened in different region server.
>>
>> I think the later region server should shutdown itself and start again. It
>> can register by api regionServerStartup
>> But not api regionServerReport
>>
>> eg: region could not be assigned by balance
>>
>> Hmaster logs:
>> 2011-05-23 11:12:10,588 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
>> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to
>> 158-1-101-82,20020,1306117051387
>> 2011-05-23 11:15:20,472 INFO
>> org.apache.hadoop.hbase.master.AssignmentManager: Regions in transition
>> timed out:  hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> state=PENDING_OPEN, ts=1306120330588
>> 2011-05-23 11:15:20,472 INFO
>> org.apache.hadoop.hbase.master.AssignmentManager: Region has been
>> PENDING_OPEN for too long, reassigning
>> region=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:15:20,513 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: Forcing OFFLINE;
>> was=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> state=PENDING_OPEN, ts=1306120330588
>> 2011-05-23 11:15:20,513 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: No previous transition
>> plan was found (or we are ignoring an existing plan) for
>> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. so generated a
>> random one;
>> hri=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d., src=,
>> dest=158-1-101-82,20020,1306117051387; 2 (online=2, exclude=null) available
>> servers
>> 2011-05-23 11:15:20,513 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
>> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to
>> 158-1-101-82,20020,1306117051387
>> 2011-05-23 11:18:30,473 INFO
>> org.apache.hadoop.hbase.master.AssignmentManager: Regions in transition
>> timed out:  hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> state=PENDING_OPEN, ts=1306120520513
>> 2011-05-23 11:18:30,473 INFO
>> org.apache.hadoop.hbase.master.AssignmentManager: Region has been
>> PENDING_OPEN for too long, reassigning
>> region=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:18:30,487 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: Forcing OFFLINE;
>> was=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> state=PENDING_OPEN, ts=1306120520513
>> 2011-05-23 11:18:30,487 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: No previous transition
>> plan was found (or we are ignoring an existing plan) for
>> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. so generated a
>> random one;
>> hri=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d., src=,
>> dest=158-1-101-222,20020,1306119315097; 2 (online=2, exclude=null) available
>> servers
>> 2011-05-23 11:18:30,488 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
>> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to
>> 158-1-101-222,20020,1306119315097
>> 2011-05-23 11:18:30,516 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: Handling
>> transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097,
>> region=70541f0abda274708e12570c52aa7f1d
>> 2011-05-23 11:18:30,581 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: Handling
>> transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097,
>> region=70541f0abda274708e12570c52aa7f1d
>> 2011-05-23 11:18:30,900 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: Handling
>> transition=RS_ZK_REGION_OPENED, server=158-1-101-222,20020,1306119315097,
>> region=70541f0abda274708e12570c52aa7f1d
>> 2011-05-23 11:18:30,900 DEBUG
>> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Handling OPENED
>> event for 70541f0abda274708e12570c52aa7f1d; deleting unassigned node
>> 2011-05-23 11:18:30,900 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
>> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Deleting
>> existing unassigned node for 70541f0abda274708e12570c52aa7f1d that is in
>> expected state RS_ZK_REGION_OPENED
>> 2011-05-23 11:18:30,930 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
>> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006
>> Successfully deleted unassigned node for region
>> 70541f0abda274708e12570c52aa7f1d in expected state RS_ZK_REGION_OPENED
>>
>>
>> Regionserver logs:
>> 2011-05-23 10:21:37,400 DEBUG
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Opened
>> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:04:19,633 INFO
>> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to open
>> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:04:19,633 DEBUG
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Processing
>> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:04:19,633 WARN
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Attempted
>> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
>> already online on this server
>> 2011-05-23 11:09:00,615 INFO
>> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to open
>> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:09:00,615 DEBUG
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Processing
>> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:09:00,615 WARN
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Attempted
>> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
>> already online on this server
>> 2011-05-23 11:12:10,588 INFO
>> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to open
>> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:12:10,588 DEBUG
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Processing
>> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:12:10,588 WARN
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Attempted
>> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
>> already online on this server
>> 2011-05-23 11:15:20,513 INFO
>> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to open
>> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:15:20,513 DEBUG
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Processing
>> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:15:20,513 WARN
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Attempted
>> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
>> already online on this server
>>
>
>

Re: About RegionServer checkin

Posted by Ted Yu <yu...@gmail.com>.
Do you see the following message in master log for 158-1-101-82 ?
      String message = "Server " + what + " rejected; currently processing "
+
          serverName + " as dead server";

Thanks

On Thu, May 26, 2011 at 4:29 AM, Ted Yu <yu...@gmail.com> wrote:

> This was from 158-1-101-82 log, right ?
>
> >> 2011-05-23 10:21:37,400 DEBUG org.apache.hadoop.hbase.
> regionserver.handler.OpenRegionHandler: Opened
> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>
> Can you paste more log before the above line ?
> Master log around 2011-05-23 10:21:37,400 would help too.
>
>
> On Thu, May 26, 2011 at 2:35 AM, Gaojinchao <ga...@huawei.com> wrote:
>
>> Sorry, I hate my poor English .
>>
>> I give a description again:
>> Master add regionserver to onlineServers in two case:
>> 1. Add a machine to the cluster, It includes cluster startup or add a new
>> machine.
>> Master can get region server information from api "regionServerStartup"
>> and add to onlineServers set.
>>
>> 2. Master is restarted.
>> Master can get region server information from api "regionServerReport" and
>> add to onlineServers set.
>> But It must be happened when Master called function
>> waitForRegionServers().
>> If region sever reported is later, Master will take it for a dead server.
>> The regions will be assigned.
>> So one region is opened in different region server.
>>
>> I think the later region server should shutdown itself and start again. It
>> can register by api regionServerStartup
>> But not api regionServerReport
>>
>> eg: region could not be assigned by balance
>>
>> Hmaster logs:
>> 2011-05-23 11:12:10,588 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
>> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to
>> 158-1-101-82,20020,1306117051387
>> 2011-05-23 11:15:20,472 INFO
>> org.apache.hadoop.hbase.master.AssignmentManager: Regions in transition
>> timed out:  hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> state=PENDING_OPEN, ts=1306120330588
>> 2011-05-23 11:15:20,472 INFO
>> org.apache.hadoop.hbase.master.AssignmentManager: Region has been
>> PENDING_OPEN for too long, reassigning
>> region=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:15:20,513 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: Forcing OFFLINE;
>> was=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> state=PENDING_OPEN, ts=1306120330588
>> 2011-05-23 11:15:20,513 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: No previous transition
>> plan was found (or we are ignoring an existing plan) for
>> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. so generated a
>> random one;
>> hri=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d., src=,
>> dest=158-1-101-82,20020,1306117051387; 2 (online=2, exclude=null) available
>> servers
>> 2011-05-23 11:15:20,513 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
>> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to
>> 158-1-101-82,20020,1306117051387
>> 2011-05-23 11:18:30,473 INFO
>> org.apache.hadoop.hbase.master.AssignmentManager: Regions in transition
>> timed out:  hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> state=PENDING_OPEN, ts=1306120520513
>> 2011-05-23 11:18:30,473 INFO
>> org.apache.hadoop.hbase.master.AssignmentManager: Region has been
>> PENDING_OPEN for too long, reassigning
>> region=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:18:30,487 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: Forcing OFFLINE;
>> was=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> state=PENDING_OPEN, ts=1306120520513
>> 2011-05-23 11:18:30,487 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: No previous transition
>> plan was found (or we are ignoring an existing plan) for
>> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. so generated a
>> random one;
>> hri=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d., src=,
>> dest=158-1-101-222,20020,1306119315097; 2 (online=2, exclude=null) available
>> servers
>> 2011-05-23 11:18:30,488 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
>> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to
>> 158-1-101-222,20020,1306119315097
>> 2011-05-23 11:18:30,516 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: Handling
>> transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097,
>> region=70541f0abda274708e12570c52aa7f1d
>> 2011-05-23 11:18:30,581 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: Handling
>> transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097,
>> region=70541f0abda274708e12570c52aa7f1d
>> 2011-05-23 11:18:30,900 DEBUG
>> org.apache.hadoop.hbase.master.AssignmentManager: Handling
>> transition=RS_ZK_REGION_OPENED, server=158-1-101-222,20020,1306119315097,
>> region=70541f0abda274708e12570c52aa7f1d
>> 2011-05-23 11:18:30,900 DEBUG
>> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Handling OPENED
>> event for 70541f0abda274708e12570c52aa7f1d; deleting unassigned node
>> 2011-05-23 11:18:30,900 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
>> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Deleting
>> existing unassigned node for 70541f0abda274708e12570c52aa7f1d that is in
>> expected state RS_ZK_REGION_OPENED
>> 2011-05-23 11:18:30,930 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
>> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006
>> Successfully deleted unassigned node for region
>> 70541f0abda274708e12570c52aa7f1d in expected state RS_ZK_REGION_OPENED
>>
>>
>> Regionserver logs:
>> 2011-05-23 10:21:37,400 DEBUG
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Opened
>> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:04:19,633 INFO
>> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to open
>> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:04:19,633 DEBUG
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Processing
>> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:04:19,633 WARN
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Attempted
>> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
>> already online on this server
>> 2011-05-23 11:09:00,615 INFO
>> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to open
>> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:09:00,615 DEBUG
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Processing
>> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:09:00,615 WARN
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Attempted
>> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
>> already online on this server
>> 2011-05-23 11:12:10,588 INFO
>> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to open
>> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:12:10,588 DEBUG
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Processing
>> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:12:10,588 WARN
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Attempted
>> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
>> already online on this server
>> 2011-05-23 11:15:20,513 INFO
>> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to open
>> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:15:20,513 DEBUG
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Processing
>> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
>> 2011-05-23 11:15:20,513 WARN
>> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Attempted
>> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
>> already online on this server
>>
>
>

Re: About RegionServer checkin

Posted by Ted Yu <yu...@gmail.com>.
This was from 158-1-101-82 log, right ?
>> 2011-05-23 10:21:37,400 DEBUG org.apache.hadoop.hbase.
regionserver.handler.OpenRegionHandler: Opened
hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.

Can you paste more log before the above line ?
Master log around 2011-05-23 10:21:37,400 would help too.

On Thu, May 26, 2011 at 2:35 AM, Gaojinchao <ga...@huawei.com> wrote:

> Sorry, I hate my poor English .
>
> I give a description again:
> Master add regionserver to onlineServers in two case:
> 1. Add a machine to the cluster, It includes cluster startup or add a new
> machine.
> Master can get region server information from api "regionServerStartup" and
> add to onlineServers set.
>
> 2. Master is restarted.
> Master can get region server information from api "regionServerReport" and
> add to onlineServers set.
> But It must be happened when Master called function waitForRegionServers().
> If region sever reported is later, Master will take it for a dead server.
> The regions will be assigned.
> So one region is opened in different region server.
>
> I think the later region server should shutdown itself and start again. It
> can register by api regionServerStartup
> But not api regionServerReport
>
> eg: region could not be assigned by balance
>
> Hmaster logs:
> 2011-05-23 11:12:10,588 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to
> 158-1-101-82,20020,1306117051387
> 2011-05-23 11:15:20,472 INFO
> org.apache.hadoop.hbase.master.AssignmentManager: Regions in transition
> timed out:  hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> state=PENDING_OPEN, ts=1306120330588
> 2011-05-23 11:15:20,472 INFO
> org.apache.hadoop.hbase.master.AssignmentManager: Region has been
> PENDING_OPEN for too long, reassigning
> region=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> 2011-05-23 11:15:20,513 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Forcing OFFLINE;
> was=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> state=PENDING_OPEN, ts=1306120330588
> 2011-05-23 11:15:20,513 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: No previous transition
> plan was found (or we are ignoring an existing plan) for
> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. so generated a
> random one;
> hri=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d., src=,
> dest=158-1-101-82,20020,1306117051387; 2 (online=2, exclude=null) available
> servers
> 2011-05-23 11:15:20,513 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to
> 158-1-101-82,20020,1306117051387
> 2011-05-23 11:18:30,473 INFO
> org.apache.hadoop.hbase.master.AssignmentManager: Regions in transition
> timed out:  hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> state=PENDING_OPEN, ts=1306120520513
> 2011-05-23 11:18:30,473 INFO
> org.apache.hadoop.hbase.master.AssignmentManager: Region has been
> PENDING_OPEN for too long, reassigning
> region=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> 2011-05-23 11:18:30,487 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Forcing OFFLINE;
> was=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> state=PENDING_OPEN, ts=1306120520513
> 2011-05-23 11:18:30,487 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: No previous transition
> plan was found (or we are ignoring an existing plan) for
> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. so generated a
> random one;
> hri=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d., src=,
> dest=158-1-101-222,20020,1306119315097; 2 (online=2, exclude=null) available
> servers
> 2011-05-23 11:18:30,488 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Assigning region
> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to
> 158-1-101-222,20020,1306119315097
> 2011-05-23 11:18:30,516 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097,
> region=70541f0abda274708e12570c52aa7f1d
> 2011-05-23 11:18:30,581 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097,
> region=70541f0abda274708e12570c52aa7f1d
> 2011-05-23 11:18:30,900 DEBUG
> org.apache.hadoop.hbase.master.AssignmentManager: Handling
> transition=RS_ZK_REGION_OPENED, server=158-1-101-222,20020,1306119315097,
> region=70541f0abda274708e12570c52aa7f1d
> 2011-05-23 11:18:30,900 DEBUG
> org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Handling OPENED
> event for 70541f0abda274708e12570c52aa7f1d; deleting unassigned node
> 2011-05-23 11:18:30,900 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Deleting
> existing unassigned node for 70541f0abda274708e12570c52aa7f1d that is in
> expected state RS_ZK_REGION_OPENED
> 2011-05-23 11:18:30,930 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign:
> master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006
> Successfully deleted unassigned node for region
> 70541f0abda274708e12570c52aa7f1d in expected state RS_ZK_REGION_OPENED
>
>
> Regionserver logs:
> 2011-05-23 10:21:37,400 DEBUG
> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Opened
> hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> 2011-05-23 11:04:19,633 INFO
> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to open
> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> 2011-05-23 11:04:19,633 DEBUG
> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Processing
> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> 2011-05-23 11:04:19,633 WARN
> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Attempted
> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
> already online on this server
> 2011-05-23 11:09:00,615 INFO
> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to open
> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> 2011-05-23 11:09:00,615 DEBUG
> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Processing
> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> 2011-05-23 11:09:00,615 WARN
> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Attempted
> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
> already online on this server
> 2011-05-23 11:12:10,588 INFO
> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to open
> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> 2011-05-23 11:12:10,588 DEBUG
> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Processing
> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> 2011-05-23 11:12:10,588 WARN
> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Attempted
> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
> already online on this server
> 2011-05-23 11:15:20,513 INFO
> org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to open
> region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> 2011-05-23 11:15:20,513 DEBUG
> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Processing
> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
> 2011-05-23 11:15:20,513 WARN
> org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Attempted
> open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but
> already online on this server
>

Re: About RegionServer checkin

Posted by Gaojinchao <ga...@huawei.com>.
Sorry, I hate my poor English .  

I give a description again: 
Master add regionserver to onlineServers in two case:
1. Add a machine to the cluster, It includes cluster startup or add a new machine.
Master can get region server information from api "regionServerStartup" and add to onlineServers set.

2. Master is restarted.
Master can get region server information from api "regionServerReport" and add to onlineServers set.
But It must be happened when Master called function waitForRegionServers().
If region sever reported is later, Master will take it for a dead server. The regions will be assigned.
So one region is opened in different region server.

I think the later region server should shutdown itself and start again. It can register by api regionServerStartup
But not api regionServerReport

eg: region could not be assigned by balance 

Hmaster logs:
2011-05-23 11:12:10,588 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Assigning region hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to 158-1-101-82,20020,1306117051387
2011-05-23 11:15:20,472 INFO org.apache.hadoop.hbase.master.AssignmentManager: Regions in transition timed out:  hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. state=PENDING_OPEN, ts=1306120330588
2011-05-23 11:15:20,472 INFO org.apache.hadoop.hbase.master.AssignmentManager: Region has been PENDING_OPEN for too long, reassigning region=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
2011-05-23 11:15:20,513 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Forcing OFFLINE; was=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. state=PENDING_OPEN, ts=1306120330588
2011-05-23 11:15:20,513 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: No previous transition plan was found (or we are ignoring an existing plan) for hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. so generated a random one; hri=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d., src=, dest=158-1-101-82,20020,1306117051387; 2 (online=2, exclude=null) available servers
2011-05-23 11:15:20,513 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Assigning region hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to 158-1-101-82,20020,1306117051387
2011-05-23 11:18:30,473 INFO org.apache.hadoop.hbase.master.AssignmentManager: Regions in transition timed out:  hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. state=PENDING_OPEN, ts=1306120520513
2011-05-23 11:18:30,473 INFO org.apache.hadoop.hbase.master.AssignmentManager: Region has been PENDING_OPEN for too long, reassigning region=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
2011-05-23 11:18:30,487 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Forcing OFFLINE; was=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. state=PENDING_OPEN, ts=1306120520513
2011-05-23 11:18:30,487 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: No previous transition plan was found (or we are ignoring an existing plan) for hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. so generated a random one; hri=hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d., src=, dest=158-1-101-222,20020,1306119315097; 2 (online=2, exclude=null) available servers
2011-05-23 11:18:30,488 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Assigning region hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. to 158-1-101-222,20020,1306119315097
2011-05-23 11:18:30,516 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Handling transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097, region=70541f0abda274708e12570c52aa7f1d
2011-05-23 11:18:30,581 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Handling transition=RS_ZK_REGION_OPENING, server=158-1-101-222,20020,1306119315097, region=70541f0abda274708e12570c52aa7f1d
2011-05-23 11:18:30,900 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Handling transition=RS_ZK_REGION_OPENED, server=158-1-101-222,20020,1306119315097, region=70541f0abda274708e12570c52aa7f1d
2011-05-23 11:18:30,900 DEBUG org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Handling OPENED event for 70541f0abda274708e12570c52aa7f1d; deleting unassigned node
2011-05-23 11:18:30,900 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Deleting existing unassigned node for 70541f0abda274708e12570c52aa7f1d that is in expected state RS_ZK_REGION_OPENED
2011-05-23 11:18:30,930 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:20000-0x2301a9c63bd0006-0x2301a9c63bd0006-0x2301a9c63bd0006 Successfully deleted unassigned node for region 70541f0abda274708e12570c52aa7f1d in expected state RS_ZK_REGION_OPENED


Regionserver logs:
2011-05-23 10:21:37,400 DEBUG org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Opened hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
2011-05-23 11:04:19,633 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to open region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
2011-05-23 11:04:19,633 DEBUG org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Processing open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
2011-05-23 11:04:19,633 WARN org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Attempted open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but already online on this server
2011-05-23 11:09:00,615 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to open region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
2011-05-23 11:09:00,615 DEBUG org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Processing open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
2011-05-23 11:09:00,615 WARN org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Attempted open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but already online on this server
2011-05-23 11:12:10,588 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to open region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
2011-05-23 11:12:10,588 DEBUG org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Processing open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
2011-05-23 11:12:10,588 WARN org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Attempted open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but already online on this server
2011-05-23 11:15:20,513 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to open region: hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
2011-05-23 11:15:20,513 DEBUG org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Processing open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d.
2011-05-23 11:15:20,513 WARN org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Attempted open of hello,150900,1305944335445.70541f0abda274708e12570c52aa7f1d. but already online on this server

Re: About RegionServer checkin

Posted by Stack <st...@duboce.net>.
2011/5/25 Gaojinchao <ga...@huawei.com>:
> How many regions in the cluster?  Do you say 1344 above?  How do we get to 5041?
>
> In my test cluster: 1 hmasters , 2 regionservers , 3 zookeeper and 5041 regions
>
> In this scenario:
> 1, Two Zookeeper crashed

What made them crash?  Are you doing recovery testing?


> 2, One Hmaster and one regionserver crashed
> 3. zookeeper started
> 4.Hmaster and regionserver started.
> 5.I found that region number is more 1000 than the fact.
>

I do not follow what you are saying above.  There are 5041 regions on
the cluster?  What are you saying above?

> I read the code and found regions should be opened two times.
> I think region server should be added to onlineServers in two case:
> 1. region server startup

Yes.  When RS starts up, it will go and send a report for duty message
to the master.

> 2. Region server checkin when Hmaster thread call waitForRegionServers()
>

So, if RS comes in after this, tell it YouAreDeadException?   What if
its just slow starting?  Or what if its a big cluster?  What if you
want to double your serving capacity?  You won't be able to just add
machines.  You'll need to kill the master after you add the machines
and then restart it?

I do not understand the problem you are seeing Gao?  Please try
explaining more.  Sorry I am being slow to understand.

St.Ack

Re: About RegionServer checkin

Posted by Gaojinchao <ga...@huawei.com>.
Yes It is case balancer assigned a portion of the total.

How many regions in the cluster?  Do you say 1344 above?  How do we get to 5041?

In my test cluster: 1 hmasters , 2 regionservers , 3 zookeeper and 5041 regions

In this scenario:
1, Two Zookeeper crashed
2, One Hmaster and one regionserver crashed
3. zookeeper started
4.Hmaster and regionserver started.
5.I found that region number is more 1000 than the fact.

I read the code and found regions should be opened two times.
I think region server should be added to onlineServers in two case:
1. region server startup 
2. Region server checkin when Hmaster thread call waitForRegionServers()

Other case region server should shutdown itself.


-----邮件原件-----
发件人: saint.ack@gmail.com [mailto:saint.ack@gmail.com] 代表 Stack
发送时间: 2011年5月25日 12:36
收件人: user@hbase.apache.org
主题: Re: About RegionServer checkin

On Tue, May 24, 2011 at 9:27 PM, Gaojinchao <ga...@huawei.com> wrote:
> If Region server checkin after call this.serverManager.waitForRegionServers().
> It seems that regionServerReport shouldn't add Region server to onlineServers.
> Otherwise The region may be opened again.
>

I don't follow?  Usually what happens is that the next time the
balancer runs, this late server gets assigned a portion of the total
regions.


> 2011-05-23 10:56:33,875 INFO org.apache.hadoop.hbase.master.AssignmentManager: Bulk assigning 5041 region(s) across 1 server(s), retainAssignment=true
> 2011-05-23 10:56:33,876 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Timeout-on-RIT=5041000

How many regions in the cluster?  Do you say 1344 above?  How do we get to 5041?

St.Ack

Re: About RegionServer checkin

Posted by Stack <st...@duboce.net>.
On Tue, May 24, 2011 at 9:27 PM, Gaojinchao <ga...@huawei.com> wrote:
> If Region server checkin after call this.serverManager.waitForRegionServers().
> It seems that regionServerReport shouldn't add Region server to onlineServers.
> Otherwise The region may be opened again.
>

I don't follow?  Usually what happens is that the next time the
balancer runs, this late server gets assigned a portion of the total
regions.


> 2011-05-23 10:56:33,875 INFO org.apache.hadoop.hbase.master.AssignmentManager: Bulk assigning 5041 region(s) across 1 server(s), retainAssignment=true
> 2011-05-23 10:56:33,876 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Timeout-on-RIT=5041000

How many regions in the cluster?  Do you say 1344 above?  How do we get to 5041?

St.Ack