Ted Yu created HBASE-12707:
------------------------------
Summary: TestMasterObserver#testTableOperations may fail due to
race condition
Key: HBASE-12707
URL: https://issues.apache.org/jira/browse/HBASE-12707
Project: HBase
Issue Type: Test
Reporter: Ted Yu
Priority: Minor
Here was the failure I saw:
{code}
testTableOperations(org.apache.hadoop.hbase.coprocessor.TestMasterObserver)
Time elapsed: 5.153 sec <<< FAILURE!
java.lang.AssertionError: Delete table handler should be called.
at org.junit.Assert.fail(Assert.java:88)
at org.junit.Assert.assertTrue(Assert.java:41)
at
org.apache.hadoop.hbase.coprocessor.TestMasterObserver.testTableOperations(TestMasterObserver.java:1302)
{code}
Here is relevant part of test output:
{code}
2014-12-18 00:18:47,788 DEBUG [MASTER_TABLE_OPERATIONS-kiyo:56800-0]
backup.HFileArchiver(438): Finished archiving from class
org.apache.hadoop.hbase.backup.HFileArchiver$FileablePath,
file:hdfs://localhost:49506/user/hortonzy/test-data/caaed63b-db6f-4dad-a455-3f63897555f7/.tmp/data/default/observed_table/294700c0c28e634c9e046d5368559666/recovered.edits/7.seqid,
to
hdfs://localhost:49506/user/hortonzy/test-data/caaed63b-db6f-4dad-a455-3f63897555f7/archive/data/default/observed_table/294700c0c28e634c9e046d5368559666/recovered.edits/7.seqid
2014-12-18 00:18:47,789 INFO [IPC Server handler 2 on 49506]
blockmanagement.BlockManager(1074): BLOCK* addToInvalidates:
blk_1073741879_1055 127.0.0.1:60154 127.0.0.1:38435
2014-12-18 00:18:47,789 DEBUG [MASTER_TABLE_OPERATIONS-kiyo:56800-0]
backup.HFileArchiver(453): Deleted all region files in:
hdfs://localhost:49506/user/hortonzy/test-data/caaed63b-db6f-4dad-a455-3f63897555f7/.tmp/data/default/observed_table/294700c0c28e634c9e046d5368559666
2014-12-18 00:18:47,790 INFO [IPC Server handler 0 on 49506]
blockmanagement.BlockManager(1074): BLOCK* addToInvalidates:
blk_1073741883_1059 127.0.0.1:60154 127.0.0.1:38435
2014-12-18 00:18:47,791 DEBUG [MASTER_TABLE_OPERATIONS-kiyo:56800-0]
handler.DeleteTableHandler(160): Table 'observed_table' archived!
2014-12-18 00:18:47,791 DEBUG [MASTER_TABLE_OPERATIONS-kiyo:56800-0]
handler.DeleteTableHandler(110): Removing 'observed_table' descriptor.
2014-12-18 00:18:47,792 DEBUG [MASTER_TABLE_OPERATIONS-kiyo:56800-0]
handler.DeleteTableHandler(116): Removing 'observed_table' from region states.
2014-12-18 00:18:47,792 DEBUG [MASTER_TABLE_OPERATIONS-kiyo:56800-0]
handler.DeleteTableHandler(120): Marking 'observed_table' as deleted.
2014-12-18 00:18:47,874 DEBUG [B.defaultRpcServer.handler=2,queue=0,port=56800]
util.FSTableDescriptors(177): Exception during readTableDecriptor. Current
table name = observed_table
org.apache.hadoop.hbase.TableInfoMissingException: No table descriptor file
under
hdfs://localhost:49506/user/hortonzy/test-data/caaed63b-db6f-4dad-a455-3f63897555f7/data/default/observed_table
at
org.apache.hadoop.hbase.util.FSTableDescriptors.getTableDescriptorFromFs(FSTableDescriptors.java:509)
at
org.apache.hadoop.hbase.util.FSTableDescriptors.getTableDescriptorFromFs(FSTableDescriptors.java:487)
at
org.apache.hadoop.hbase.util.FSTableDescriptors.get(FSTableDescriptors.java:172)
at
org.apache.hadoop.hbase.master.HMaster.listTableDescriptors(HMaster.java:2166)
at
org.apache.hadoop.hbase.master.MasterRpcServices.getTableDescriptors(MasterRpcServices.java:788)
at
org.apache.hadoop.hbase.protobuf.generated.MasterProtos$MasterService$2.callBlockingMethod(MasterProtos.java:42402)
at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2028)
at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:108)
at
org.apache.hadoop.hbase.ipc.RpcExecutor.consumerLoop(RpcExecutor.java:112)
at org.apache.hadoop.hbase.ipc.RpcExecutor$1.run(RpcExecutor.java:92)
at java.lang.Thread.run(Thread.java:724)
2014-12-18 00:18:47,875 INFO [main] client.HBaseAdmin(738): Deleted
observed_table
2014-12-18 00:18:47,880 WARN [main] hbase.MetaTableAccessor$1(344): No
serialized HRegionInfo in
keyvalues={observed_table,,1418861912253.8551edbe4ffb771a607ad362bfc6642d./info:seqnumDuringOpen/1418861917732/Put/vlen=8/seqid=0,
observed_table,,1418861912253.8551edbe4ffb771a607ad362bfc6642d./info:server/1418861917732/Put/vlen=28/seqid=0,
observed_table,,1418861912253.8551edbe4ffb771a607ad362bfc6642d./info:serverstartcode/1418861917732/Put/vlen=8/seqid=0}
2014-12-18 00:18:47,924 INFO [main] hbase.ResourceChecker(171): after:
coprocessor.TestMasterObserver#testTableOperations Thread=600 (was 475)
{code}
Here is related code in DeleteTableHandler#handleTableOperation():
{code}
removeTableData(regions);
if (cpHost != null) {
cpHost.postDeleteTableHandler(this.tableName);
{code}
Table data is removed first, then postDeleteTableHandler is called.
However, the loop in HBaseAdmin checks for the presence of TableDescriptor. The
loop exits if TableDescriptor is not found. Hence the assertion in test may be
executed earlier than postDeleteTableHandler is called, leading to test failure.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
