[HBASE-12685] TestSplitLogManager#testLogFilesAreArchived sometimes times out due to race condition

• Type: Test
• Status: Closed
• Priority: Minor
• Resolution: Fixed
• Fix Version/s: 1.0.0, 0.98.9
• Hadoop Flags: Reviewed
• Assignee: Ted Yu
• Reporter: Ted Yu
• Created: 14/Dec/14 18:19
• Updated: 06/Apr/18 17:54
• Resolved: 15/Dec/14 19:54

Description

From https://builds.apache.org/job/hbase-0.98/739/testReport/org.apache.hadoop.hbase.master/TestSplitLogManager/testLogFilesAreArchived/ :

2014-12-14 14:40:30,420 INFO  [Thread-27] master.SplitLogManager(325): started splitting 1 logs in [/home/jenkins/jenkins-slave/workspace/HBase-0.98/hbase-server/target/test-data/c065c13d-bc83-48e7-9178-51a14df531c3/testLogFilesAreArchived/f7ae1e8f-c848-4089-b5b1-20aff73c81dd]
2014-12-14 14:40:30,422 WARN  [Thread-31] master.TestSplitLogManager$5(527): org.apache.zookeeper.KeeperException$NoNodeException: KeeperErrorCode = NoNode for /hbase/splitWAL/f7ae1e8f-c848-4089-b5b1-20aff73c81dd%2Ffoo%2C1%2C1
2014-12-14 14:40:30,423 DEBUG [main-EventThread] master.SplitLogManager(703): put up splitlog task at znode /hbase/splitWAL/f7ae1e8f-c848-4089-b5b1-20aff73c81dd%2Ffoo%2C1%2C1

The thread which mocks split done called ZKUtil.setData() before SplitLogManager put up the splitlog task znode. The setting of done to true should exclude the above scenario.
Otherwise log split task would miss the split done mock, resulting in test failure:

2014-12-14 14:41:18,562 INFO  [main-EventThread] master.SplitLogManager(753): task /hbase/splitWAL/RESCAN0000000004 entered state: DONE dummy-master,1,1
2014-12-14 14:41:18,563 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(312): split-log-manager-testsa62d20ae-9904-4dc6-9e79-b7d98486dd49-0x14a493e58af0000, quorum=localhost:50869, baseZNode=/hbase Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/splitWAL/RESCAN0000000004
2014-12-14 14:41:18,563 DEBUG [main-EventThread] master.SplitLogManager$DeleteAsyncCallback(1712): deleted /hbase/splitWAL/RESCAN0000000004
2014-12-14 14:41:18,563 DEBUG [main-EventThread] master.SplitLogManager(935): deleted task without in memory state /hbase/splitWAL/RESCAN0000000004
2014-12-14 14:41:20,562 INFO  [dummy-master,1,1.splitLogManagerTimeoutMonitor] master.SplitLogManager$TimeoutMonitor(1502): total tasks = 1 unassigned = 1 tasks={/hbase/splitWAL/f7ae1e8f-c848-4089-b5b1-20aff73c81dd%2Ffoo%2C1%2C1=last_update = -1 last_version = -1 cur_worker_name = null status = in_progress incarnation = 0 resubmits = 0 batch = installed = 1 done = 0 error = 0}
2014-12-14 14:41:25,568 INFO  [dummy-master,1,1.splitLogManagerTimeoutMonitor] master.SplitLogManager$TimeoutMonitor(1502): total tasks = 1 unassigned = 1 tasks={/hbase/splitWAL/f7ae1e8f-c848-4089-b5b1-20aff73c81dd%2Ffoo%2C1%2C1=last_update = -1 last_version = -1 cur_worker_name = null status = in_progress incarnation = 0 resubmits = 0 batch = installed = 1 done = 0 error = 0}
2014-12-14 14:41:30,399 WARN  [Thread-27] master.SplitLogManager(441): Interrupted while waiting for log splits to be completed