[
https://issues.apache.org/jira/browse/HBASE-8632?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13669337#comment-13669337
]
Andrew Purtell commented on HBASE-8632:
---------------------------------------
Are you planning to put up a patch Ted?
> TestAccessController#testGlobalAuthorizationForNewRegisteredRS fails
> intermittently due to prolonged region movement
> --------------------------------------------------------------------------------------------------------------------
>
> Key: HBASE-8632
> URL: https://issues.apache.org/jira/browse/HBASE-8632
> Project: HBase
> Issue Type: Test
> Reporter: Ted Yu
>
> Here is test output from
> https://builds.apache.org/job/PreCommit-HBASE-Build/5852/testReport/org.apache.hadoop.hbase.security.access/TestAccessController/testGlobalAuthorizationForNewRegisteredRS/:
> {code}
> 2013-05-28 19:54:07,360 INFO [PRI IPC Server handler 0 on 58791]
> regionserver.HRegionServer(3535): Received close region:
> 4700bdd89a351b506da910dd6a268d44Transitioning in ZK: yes. Version of ZK
> closing node:0. Destination
> server:asf001.sp2.ygridcore.net,36189,1369770847288
> 2013-05-28 19:54:07,360 DEBUG
> [RS_CLOSE_REGION-asf001.sp2.ygridcore.net,58791,1369770680000-1]
> handler.CloseRegionHandler(125): Processing close of
> testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> 2013-05-28 19:54:07,360 DEBUG [IPC Server handler 2 on 55436]
> master.AssignmentManager(1672): Sent CLOSE to
> asf001.sp2.ygridcore.net,58791,1369770680000 for region
> testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> 2013-05-28 19:54:07,360 DEBUG [pool-1-thread-1]
> access.TestAccessController(1955): Waiting for region to be opened. Already
> retried 0 times.
> 2013-05-28 19:54:07,361 DEBUG
> [RS_CLOSE_REGION-asf001.sp2.ygridcore.net,58791,1369770680000-1]
> regionserver.HRegion(928): Closing
> testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.: disabling
> compactions & flushes
> 2013-05-28 19:54:07,361 DEBUG
> [RS_CLOSE_REGION-asf001.sp2.ygridcore.net,58791,1369770680000-1]
> regionserver.HRegion(950): Updates disabled for region
> testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> 2013-05-28 19:54:07,362 INFO
> [StoreCloserThread-testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.-1]
> regionserver.HStore(663): Closed f1
> 2013-05-28 19:54:07,362 INFO
> [RS_CLOSE_REGION-asf001.sp2.ygridcore.net,58791,1369770680000-1]
> regionserver.HRegion(1007): Closed
> testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> 2013-05-28 19:54:07,362 INFO
> [RS_CLOSE_REGION-asf001.sp2.ygridcore.net,58791,1369770680000-1]
> regionserver.HRegionServer(4060): Adding moved region record:
> 4700bdd89a351b506da910dd6a268d44 to
> asf001.sp2.ygridcore.net,36189,1369770847288:36189 as of 1
> 2013-05-28 19:54:07,363 DEBUG
> [RS_CLOSE_REGION-asf001.sp2.ygridcore.net,58791,1369770680000-1]
> zookeeper.ZKAssign(786): regionserver:58791-0x13eecb1db960001 Attempting to
> transition node 4700bdd89a351b506da910dd6a268d44 from M_ZK_REGION_CLOSING to
> RS_ZK_REGION_CLOSED
> 2013-05-28 19:54:07,561 DEBUG [pool-1-thread-1]
> access.TestAccessController(1955): Waiting for region to be opened. Already
> retried 1 times.
> 2013-05-28 19:54:07,761 DEBUG [pool-1-thread-1]
> access.TestAccessController(1955): Waiting for region to be opened. Already
> retried 2 times.
> 2013-05-28 19:54:07,961 DEBUG [pool-1-thread-1]
> access.TestAccessController(1955): Waiting for region to be opened. Already
> retried 3 times.
> 2013-05-28 19:54:08,162 DEBUG [pool-1-thread-1]
> access.TestAccessController(1955): Waiting for region to be opened. Already
> retried 4 times.
> 2013-05-28 19:54:08,362 DEBUG [pool-1-thread-1]
> access.TestAccessController(1955): Waiting for region to be opened. Already
> retried 5 times.
> 2013-05-28 19:54:08,562 DEBUG [pool-1-thread-1]
> access.TestAccessController(1955): Waiting for region to be opened. Already
> retried 6 times.
> 2013-05-28 19:54:08,763 DEBUG [pool-1-thread-1]
> access.TestAccessController(1955): Waiting for region to be opened. Already
> retried 7 times.
> 2013-05-28 19:54:08,963 DEBUG [pool-1-thread-1]
> access.TestAccessController(1955): Waiting for region to be opened. Already
> retried 8 times.
> 2013-05-28 19:54:09,164 INFO [pool-1-thread-1] client.HBaseAdmin$5(834):
> Started disable of testtable
> 2013-05-28 19:54:09,320 DEBUG [pool-1-thread-1-EventThread]
> zookeeper.ZooKeeperWatcher(307): master:55436-0x13eecb1db960000 Received
> ZooKeeper Event, type=NodeDataChanged, state=SyncConnected,
> path=/hbase/region-in-transition/4700bdd89a351b506da910dd6a268d44
> 2013-05-28 19:54:09,320 DEBUG
> [RS_CLOSE_REGION-asf001.sp2.ygridcore.net,58791,1369770680000-1]
> zookeeper.ZKAssign(862): regionserver:58791-0x13eecb1db960001 Successfully
> transitioned node 4700bdd89a351b506da910dd6a268d44 from M_ZK_REGION_CLOSING
> to RS_ZK_REGION_CLOSED
> 2013-05-28 19:54:09,321 DEBUG
> [RS_CLOSE_REGION-asf001.sp2.ygridcore.net,58791,1369770680000-1]
> handler.CloseRegionHandler(168): set region closed state in zk successfully
> for region testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44. sn
> name: asf001.sp2.ygridcore.net,58791,1369770680000
> 2013-05-28 19:54:09,321 DEBUG
> [RS_CLOSE_REGION-asf001.sp2.ygridcore.net,58791,1369770680000-1]
> handler.CloseRegionHandler(177): Closed region
> testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> 2013-05-28 19:54:09,322 DEBUG [hbase-am-zkevent-worker-pool-2-thread-20]
> master.AssignmentManager(752): Handling transition=RS_ZK_REGION_CLOSED,
> server=asf001.sp2.ygridcore.net,58791,1369770680000,
> region=4700bdd89a351b506da910dd6a268d44, current state from region state map
> ={testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> state=PENDING_CLOSE, ts=1369770847359,
> server=asf001.sp2.ygridcore.net,58791,1369770680000}
> 2013-05-28 19:54:09,322 WARN [hbase-am-zkevent-worker-pool-2-thread-20]
> master.RegionStates(251): Closed region {NAME =>
> 'testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.', STARTKEY =>
> '', ENDKEY => '', ENCODED => 4700bdd89a351b506da910dd6a268d44,} still on
> asf001.sp2.ygridcore.net,58791,1369770680000? Ignored, reset it to null
> 2013-05-28 19:54:09,322 INFO [hbase-am-zkevent-worker-pool-2-thread-20]
> master.RegionStates(264): Region {NAME =>
> 'testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.', STARTKEY =>
> '', ENDKEY => '', ENCODED => 4700bdd89a351b506da910dd6a268d44,} transitioned
> from {testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> state=PENDING_CLOSE, ts=1369770847359,
> server=asf001.sp2.ygridcore.net,58791,1369770680000} to
> {testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44. state=CLOSED,
> ts=1369770849322, server=null}
> 2013-05-28 19:54:09,322 DEBUG
> [MASTER_CLOSE_REGION-asf001.sp2.ygridcore.net,55436,1369770679588-0]
> handler.ClosedRegionHandler(92): Handling CLOSED event for
> 4700bdd89a351b506da910dd6a268d44
> 2013-05-28 19:54:09,322 INFO
> [MASTER_CLOSE_REGION-asf001.sp2.ygridcore.net,55436,1369770679588-0]
> master.RegionStates(264): Region {NAME =>
> 'testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.', STARTKEY =>
> '', ENDKEY => '', ENCODED => 4700bdd89a351b506da910dd6a268d44,} transitioned
> from {testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> state=CLOSED, ts=1369770849322, server=null} to
> {testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44. state=CLOSED,
> ts=1369770849322, server=null}
> 2013-05-28 19:54:09,322 DEBUG
> [MASTER_CLOSE_REGION-asf001.sp2.ygridcore.net,55436,1369770679588-0]
> master.AssignmentManager(1738): Forcing OFFLINE;
> was={testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> state=CLOSED, ts=1369770849322, server=null}
> 2013-05-28 19:54:09,323 INFO
> [MASTER_CLOSE_REGION-asf001.sp2.ygridcore.net,55436,1369770679588-0]
> master.RegionStates(264): Region {NAME =>
> 'testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.', STARTKEY =>
> '', ENDKEY => '', ENCODED => 4700bdd89a351b506da910dd6a268d44,} transitioned
> from {testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> state=CLOSED, ts=1369770849322, server=null} to
> {testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44. state=OFFLINE,
> ts=1369770849323, server=null}
> 2013-05-28 19:54:09,323 DEBUG
> [MASTER_CLOSE_REGION-asf001.sp2.ygridcore.net,55436,1369770679588-0]
> master.AssignmentManager(2056): Found an existing plan for
> testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44. destination
> server is asf001.sp2.ygridcore.net,36189,1369770847288 accepted as a dest
> server = true
> 2013-05-28 19:54:09,323 DEBUG
> [MASTER_CLOSE_REGION-asf001.sp2.ygridcore.net,55436,1369770679588-0]
> master.AssignmentManager(2095): Using pre-existing plan for region
> testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.;
> plan=hri=testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.,
> src=asf001.sp2.ygridcore.net,58791,1369770680000,
> dest=asf001.sp2.ygridcore.net,36189,1369770847288
> 2013-05-28 19:54:09,323 INFO
> [MASTER_CLOSE_REGION-asf001.sp2.ygridcore.net,55436,1369770679588-0]
> master.RegionStates(264): Region {NAME =>
> 'testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.', STARTKEY =>
> '', ENDKEY => '', ENCODED => 4700bdd89a351b506da910dd6a268d44,} transitioned
> from {testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> state=OFFLINE, ts=1369770849323, server=null} to
> {testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44. state=OFFLINE,
> ts=1369770849323, server=null}
> 2013-05-28 19:54:09,323 DEBUG
> [MASTER_CLOSE_REGION-asf001.sp2.ygridcore.net,55436,1369770679588-0]
> zookeeper.ZKAssign(208): master:55436-0x13eecb1db960000 Creating (or
> updating) unassigned node for 4700bdd89a351b506da910dd6a268d44 with OFFLINE
> state
> 2013-05-28 19:54:09,323 DEBUG [IPC Server handler 2 on 55436]
> lock.ZKInterProcessLockBase(226): Acquired a lock for
> /hbase/table-lock/testtable/write-master:554360000000001
> 2013-05-28 19:54:09,325 DEBUG [IPC Server handler 2 on 55436]
> client.ClientScanner(96): Creating scanner over .META. starting at key
> 'testtable,,'
> 2013-05-28 19:54:09,325 DEBUG [pool-1-thread-1-EventThread]
> zookeeper.ZooKeeperWatcher(307): master:55436-0x13eecb1db960000 Received
> ZooKeeper Event, type=NodeDataChanged, state=SyncConnected,
> path=/hbase/region-in-transition/4700bdd89a351b506da910dd6a268d44
> 2013-05-28 19:54:09,326 DEBUG [hbase-am-zkevent-worker-pool-2-thread-2]
> master.AssignmentManager(752): Handling transition=M_ZK_REGION_OFFLINE,
> server=asf001.sp2.ygridcore.net,36189,1369770847288,
> region=4700bdd89a351b506da910dd6a268d44, current state from region state map
> ={testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44. state=OFFLINE,
> ts=1369770849323, server=null}
> 2013-05-28 19:54:09,326 INFO
> [MASTER_CLOSE_REGION-asf001.sp2.ygridcore.net,55436,1369770679588-0]
> master.AssignmentManager(1814): Assigning region
> testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44. to
> asf001.sp2.ygridcore.net,36189,1369770847288
> 2013-05-28 19:54:09,326 INFO
> [MASTER_CLOSE_REGION-asf001.sp2.ygridcore.net,55436,1369770679588-0]
> master.RegionStates(264): Region {NAME =>
> 'testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.', STARTKEY =>
> '', ENDKEY => '', ENCODED => 4700bdd89a351b506da910dd6a268d44,} transitioned
> from {testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> state=OFFLINE, ts=1369770849323, server=null} to
> {testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> state=PENDING_OPEN, ts=1369770849326,
> server=asf001.sp2.ygridcore.net,36189,1369770847288}
> 2013-05-28 19:54:09,327 DEBUG
> [MASTER_CLOSE_REGION-asf001.sp2.ygridcore.net,55436,1369770679588-0]
> master.ServerManager(736): New admin connection to
> asf001.sp2.ygridcore.net,36189,1369770847288
> 2013-05-28 19:54:09,329 INFO [PRI IPC Server handler 0 on 36189]
> regionserver.HRegionServer(3414): Received request to open region:
> testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44. on
> asf001.sp2.ygridcore.net,36189,1369770847288
> 2013-05-28 19:54:09,329 DEBUG [IPC Server handler 2 on 55436]
> client.ClientScanner(195): Finished scanning region {NAME => '.META.,,1',
> STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,}
> 2013-05-28 19:54:09,332 INFO
> [MASTER_TABLE_OPERATIONS-asf001.sp2.ygridcore.net,55436,1369770679588-0]
> handler.DisableTableHandler(127): Attempting to disable table testtable
> 2013-05-28 19:54:09,333 DEBUG
> [RS_OPEN_REGION-asf001.sp2.ygridcore.net,36189,1369770847288-0]
> zookeeper.ZKAssign(786): regionserver:36189-0x13eecb1db9600e8 Attempting to
> transition node 4700bdd89a351b506da910dd6a268d44 from M_ZK_REGION_OFFLINE to
> RS_ZK_REGION_OPENING
> 2013-05-28 19:54:09,333 DEBUG [pool-1-thread-1] client.HBaseAdmin(870):
> Sleeping= 1000ms, waiting for all regions to be disabled in testtable
> 2013-05-28 19:54:09,334 INFO
> [MASTER_TABLE_OPERATIONS-asf001.sp2.ygridcore.net,55436,1369770679588-0]
> handler.DisableTableHandler(171): Offlining 1 regions.
> 2013-05-28 19:54:09,334 DEBUG
> [asf001.sp2.ygridcore.net,55436,1369770679588-org.apache.hadoop.hbase.master.handler.DisableTableHandler$BulkDisabler-0]
> master.AssignmentManager(2165): Starting unassignment of region
> testtable,,1369770844620.5e30eb0adeaaf6937caaba5397316ea6. (offlining)
> 2013-05-28 19:54:09,334 DEBUG
> [asf001.sp2.ygridcore.net,55436,1369770679588-org.apache.hadoop.hbase.master.handler.DisableTableHandler$BulkDisabler-0]
> zookeeper.ZKAssign(481): master:55436-0x13eecb1db960000 Creating unassigned
> node for 5e30eb0adeaaf6937caaba5397316ea6 in a CLOSING state
> 2013-05-28 19:54:09,335 DEBUG [pool-1-thread-1-EventThread]
> zookeeper.ZooKeeperWatcher(307): master:55436-0x13eecb1db960000 Received
> ZooKeeper Event, type=NodeDataChanged, state=SyncConnected,
> path=/hbase/region-in-transition/4700bdd89a351b506da910dd6a268d44
> 2013-05-28 19:54:09,335 DEBUG
> [RS_OPEN_REGION-asf001.sp2.ygridcore.net,36189,1369770847288-0]
> zookeeper.ZKAssign(862): regionserver:36189-0x13eecb1db9600e8 Successfully
> transitioned node 4700bdd89a351b506da910dd6a268d44 from M_ZK_REGION_OFFLINE
> to RS_ZK_REGION_OPENING
> 2013-05-28 19:54:09,336 INFO
> [RS_OPEN_REGION-asf001.sp2.ygridcore.net,36189,1369770847288-0]
> regionserver.HRegion(4139): HRegion.openHRegion Region name
> ==testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> 2013-05-28 19:54:09,336 DEBUG
> [RS_OPEN_REGION-asf001.sp2.ygridcore.net,36189,1369770847288-0]
> regionserver.HRegion(4141): Opening region: {NAME =>
> 'testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.', STARTKEY =>
> '', ENDKEY => '', ENCODED => 4700bdd89a351b506da910dd6a268d44,}
> 2013-05-28 19:54:09,336 DEBUG [pool-1-thread-1-EventThread]
> zookeeper.ZooKeeperWatcher(307): master:55436-0x13eecb1db960000 Received
> ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected,
> path=/hbase/region-in-transition
> 2013-05-28 19:54:09,336 DEBUG
> [RS_OPEN_REGION-asf001.sp2.ygridcore.net,36189,1369770847288-0]
> regionserver.HRegion(5106): Registered coprocessor service:
> region=testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> service=AccessControlService
> 2013-05-28 19:54:09,336 DEBUG [hbase-am-zkevent-worker-pool-2-thread-1]
> master.AssignmentManager(752): Handling transition=RS_ZK_REGION_OPENING,
> server=asf001.sp2.ygridcore.net,36189,1369770847288,
> region=4700bdd89a351b506da910dd6a268d44, current state from region state map
> ={testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> state=PENDING_OPEN, ts=1369770849326,
> server=asf001.sp2.ygridcore.net,36189,1369770847288}
> 2013-05-28 19:54:09,336 INFO [hbase-am-zkevent-worker-pool-2-thread-1]
> master.RegionStates(264): Region {NAME =>
> 'testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.', STARTKEY =>
> '', ENDKEY => '', ENCODED => 4700bdd89a351b506da910dd6a268d44,} transitioned
> from {testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> state=PENDING_OPEN, ts=1369770849326,
> server=asf001.sp2.ygridcore.net,36189,1369770847288} to
> {testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44. state=OPENING,
> ts=1369770849336, server=asf001.sp2.ygridcore.net,36189,1369770847288}
> {code}
> The region being moved was
> testtable2,,1369770846203.4700bdd89a351b506da910dd6a268d44.
> We could see that the test exhausted retries in 1.5 seconds:
> {code}
> 2013-05-28 19:54:08,963 DEBUG [pool-1-thread-1]
> access.TestAccessController(1955): Waiting for region to be opened. Already
> retried 8 times.
> {code}
> But the region movement continued after 2013-05-28 19:54:08,963
> Looks like more time should be allowed for region movement
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
