hbase-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Ted Yu (JIRA)" <j...@apache.org>
Subject [jira] [Created] (HBASE-8632) TestAccessController#testGlobalAuthorizationForNewRegisteredRS fails intermittently due to
Date Tue, 28 May 2013 21:32:19 GMT
Ted Yu created HBASE-8632:
-----------------------------

             Summary: TestAccessController#testGlobalAuthorizationForNewRegisteredRS fails
intermittently due to 
                 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

Mime
View raw message