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.
