[HBASE-12707] TestMasterObserver#testTableOperations may fail due to race condition

• Type: Test
• Status: Closed
• Priority: Minor
• Resolution: Cannot Reproduce
• Assignee: Unassigned
• Reporter: Ted Yu
• Created: 18/Dec/14 00:51
• Updated: 17/Jun/22 18:46
• Resolved: 04/Jul/15 14:31

Description

Here was the failure I saw:

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)

Here is relevant part of test output:

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)

Here is related code in DeleteTableHandler#handleTableOperation():

    removeTableData(regions);

    if (cpHost != null) {
      cpHost.postDeleteTableHandler(this.tableName);

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.