Uploaded image for project: 'HBase'
  1. HBase
  2. HBASE-12685

TestSplitLogManager#testLogFilesAreArchived sometimes times out due to race condition

    XMLWordPrintableJSON

    Details

    • Type: Test
    • Status: Closed
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 1.0.0, 0.98.9
    • Component/s: None
    • Labels:
      None
    • Hadoop Flags:
      Reviewed

      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
      

        Attachments

        1. 12685-v1.txt
          1 kB
          Ted Yu

          Activity

            People

            • Assignee:
              yuzhihong@gmail.com Ted Yu
              Reporter:
              yuzhihong@gmail.com Ted Yu
            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: