You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@hbase.apache.org by "Andrew Purtell (JIRA)" <ji...@apache.org> on 2013/05/29 17:17:20 UTC
[jira] [Commented] (HBASE-8632)
TestAccessController#testGlobalAuthorizationForNewRegisteredRS fails
intermittently due to prolonged region movement
[ 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