It reproduces easily. In my cluster, It reproduces when balance region. Log is: 2011-04-15 14:54:21,885 INFO org.apache.hadoop.hbase.master.HMaster: balance hri=ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0., src=C4C3.site,60020,1302849920122,
Today , I will open ZK client debug log and keep digging. I will try to make state chart, then can understand easily for assigning a region. -----邮件原件----- 发件人: jdcry...@gmail.com [mailto:jdcry...@gmail.com] 代表 Jean-Daniel Cryans 发送时间: 2011年4月16日 1:56 收件人: user@hbase.apache.org 主题: Re: a lots of error about Region has been OPEN for too long Yeah it's not clear from the logs why it did that, and looking through my logs I can't see any occurrence. Can you reproduce it easily? J-D On Fri, Apr 15, 2011 at 12:46 AM, Gaojinchao <gaojinc...@huawei.com> wrote: > Thanks for your reply. > > Hbase version : 0.90.1 > > I find other abnormal logs. > Hmaster receives twice RS_ZK_REGION_OPENED event. > It reproduces in balance processing. > But I can't root out what brings on ? > > Hmaster logs: > 2011-04-15 14:54:21,885 INFO org.apache.hadoop.hbase.master.HMaster: balance > hri=ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0., > src=C4C3.site,60020,1302849920122, dest=C4C5.site,60020,1302849920117 > 2011-04-15 14:54:21,885 DEBUG > org.apache.hadoop.hbase.master.AssignmentManager: Starting unassignment of > region ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0. > (offlining) > 2011-04-15 14:54:21,886 DEBUG > org.apache.hadoop.hbase.master.AssignmentManager: Sent CLOSE to > serverName=C4C3.site,60020,1302849920122, load=(requests=0, regions=588, > usedHeap=122, maxHeap=8175) for region > ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0. > 2011-04-15 14:54:25,333 DEBUG > org.apache.hadoop.hbase.master.AssignmentManager: Handling new unassigned > node: /hbase/unassigned/89e2c4452de2864bf3362a8f16e758d0 > (region=ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0., > server=C4C3.site,60020,1302849920122, state=RS_ZK_REGION_CLOSED) > 2011-04-15 14:54:25,333 DEBUG > org.apache.hadoop.hbase.master.AssignmentManager: Handling > transition=RS_ZK_REGION_CLOSED, server=C4C3.site,60020,1302849920122, > region=89e2c4452de2864bf3362a8f16e758d0 > 2011-04-15 14:55:14,364 DEBUG > org.apache.hadoop.hbase.master.handler.ClosedRegionHandler: Handling CLOSED > event for 89e2c4452de2864bf3362a8f16e758d0 > 2011-04-15 14:55:14,380 DEBUG > org.apache.hadoop.hbase.master.AssignmentManager: Forcing OFFLINE; > was=ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0. > state=CLOSED, ts=1302850513941 > 2011-04-15 14:55:14,380 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: > master:60000-0x2f57e8192e0000 Creating (or updating) unassigned node for > 89e2c4452de2864bf3362a8f16e758d0 with OFFLINE state > 2011-04-15 14:55:14,614 DEBUG > org.apache.hadoop.hbase.master.AssignmentManager: Using pre-existing plan for > region > ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0.; > plan=hri=ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0., > src=C4C3.site,60020,1302849920122, dest=C4C5.site,60020,1302849920117 > 2011-04-15 14:55:14,614 DEBUG > org.apache.hadoop.hbase.master.AssignmentManager: Assigning region > ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0. to > C4C5.site,60020,1302849920117 > 2011-04-15 14:55:14,705 DEBUG > org.apache.hadoop.hbase.master.AssignmentManager: Handling > transition=RS_ZK_REGION_OPENING, server=C4C5.site,60020,1302849920117, > region=89e2c4452de2864bf3362a8f16e758d0 > > 2011-04-15 14:55:14,714 DEBUG > org.apache.hadoop.hbase.master.AssignmentManager: Handling > transition=RS_ZK_REGION_OPENED, server=C4C5.site,60020,1302849920117, > region=89e2c4452de2864bf3362a8f16e758d0 > > //repetition > 2011-04-15 14:55:14,714 DEBUG > org.apache.hadoop.hbase.master.AssignmentManager: Handling > transition=RS_ZK_REGION_OPENED, server=C4C5.site,60020,1302849920117, > region=89e2c4452de2864bf3362a8f16e758d0 > > // Hmaster abnormal logs > 2011-04-15 14:55:14,715 WARN > org.apache.hadoop.hbase.master.AssignmentManager: Received OPENED for region > 89e2c4452de2864bf3362a8f16e758d0 from server C4C5.site,60020,1302849920117 > but region was in the state > ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0. > state=OPEN, ts=1302850514694 and not in expected PENDING_OPEN or OPENING > states > > 2011-04-15 14:55:42,362 DEBUG > org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Handling OPENED > event for 89e2c4452de2864bf3362a8f16e758d0; deleting unassigned node > 2011-04-15 14:55:42,362 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: > master:60000-0x2f57e8192e0000 Deleting existing unassigned node for > 89e2c4452de2864bf3362a8f16e758d0 that is in expected state RS_ZK_REGION_OPENED > 2011-04-15 14:55:42,392 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: > master:60000-0x2f57e8192e0000 Successfully deleted unassigned node for region > 89e2c4452de2864bf3362a8f16e758d0 in expected state RS_ZK_REGION_OPENED > 2011-04-15 14:55:42,411 DEBUG > org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Opened region > ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0. on > C4C5.site,60020,1302849920117 > > > Region server logs: > 2011-04-15 14:55:14,603 INFO > org.apache.hadoop.hbase.regionserver.HRegionServer: Received request to open > region: ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0. > 2011-04-15 14:55:14,617 DEBUG > org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Processing > open of ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0. > 2011-04-15 14:55:14,617 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: > regionserver:60020-0x2f57e8192e0004 Attempting to transition node > 89e2c4452de2864bf3362a8f16e758d0 from M_ZK_REGION_OFFLINE to > RS_ZK_REGION_OPENING > 2011-04-15 14:55:14,644 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: > regionserver:60020-0x2f57e8192e0004 Successfully transitioned node > 89e2c4452de2864bf3362a8f16e758d0 from M_ZK_REGION_OFFLINE to > RS_ZK_REGION_OPENING > 2011-04-15 14:55:14,644 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: > Opening region: REGION => {NAME => > 'ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0.', > STARTKEY => '1088613823076918', ENDKEY => '1088613826923071', ENCODED => > 89e2c4452de2864bf3362a8f16e758d0, TABLE => {{NAME => 'ufdrA', FAMILIES => > [{NAME => 'value', BLOOMFILTER => 'NONE', REPLICATION_SCOPE => '0', VERSIONS > => '3', COMPRESSION => 'GZ', TTL => '86400', BLOCKSIZE => '65536', IN_MEMORY > => 'false', BLOCKCACHE => 'true'}]}} > 2011-04-15 14:55:14,644 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: > Instantiated > ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0. > 2011-04-15 14:55:14,648 INFO org.apache.hadoop.hbase.regionserver.HRegion: > Onlined > ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0.; next > sequenceid=1 > 2011-04-15 14:55:14,648 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: > regionserver:60020-0x2f57e8192e0004 Attempting to transition node > 89e2c4452de2864bf3362a8f16e758d0 from RS_ZK_REGION_OPENING to > RS_ZK_REGION_OPENING > 2011-04-15 14:55:14,677 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: > regionserver:60020-0x2f57e8192e0004 Successfully transitioned node > 89e2c4452de2864bf3362a8f16e758d0 from RS_ZK_REGION_OPENING to > RS_ZK_REGION_OPENING > 2011-04-15 14:55:14,680 INFO org.apache.hadoop.hbase.catalog.MetaEditor: > Updated row > ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0. in > region .META.,,1 with server=C4C5.site:60020, startcode=1302849920117 > 2011-04-15 14:55:14,680 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: > regionserver:60020-0x2f57e8192e0004 Attempting to transition node > 89e2c4452de2864bf3362a8f16e758d0 from RS_ZK_REGION_OPENING to > RS_ZK_REGION_OPENED > 2011-04-15 14:55:14,702 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: > regionserver:60020-0x2f57e8192e0004 Successfully transitioned node > 89e2c4452de2864bf3362a8f16e758d0 from RS_ZK_REGION_OPENING to > RS_ZK_REGION_OPENED > 2011-04-15 14:55:14,702 DEBUG > org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler: Opened > ufdrA,1088613823076918,1301646236458.89e2c4452de2864bf3362a8f16e758d0.