Return-Path: X-Original-To: apmail-hbase-issues-archive@www.apache.org Delivered-To: apmail-hbase-issues-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 3DE3FDD7F for ; Tue, 28 May 2013 21:32:22 +0000 (UTC) Received: (qmail 77930 invoked by uid 500); 28 May 2013 21:32:21 -0000 Delivered-To: apmail-hbase-issues-archive@hbase.apache.org Received: (qmail 77894 invoked by uid 500); 28 May 2013 21:32:21 -0000 Mailing-List: contact issues-help@hbase.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Delivered-To: mailing list issues@hbase.apache.org Received: (qmail 77847 invoked by uid 99); 28 May 2013 21:32:21 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 28 May 2013 21:32:21 +0000 Date: Tue, 28 May 2013 21:32:21 +0000 (UTC) From: "Ted Yu (JIRA)" To: issues@hbase.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Updated] (HBASE-8632) TestAccessController#testGlobalAuthorizationForNewRegisteredRS fails intermittently due to prolonged region movement MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/HBASE-8632?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Ted Yu updated HBASE-8632: -------------------------- Summary: TestAccessController#testGlobalAuthorizationForNewRegisteredRS fails intermittently due to prolonged region movement (was: TestAccessController#testGlobalAuthorizationForNewRegisteredRS fails intermittently due to ) > 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