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
