HBase-4416 Report

https://issues.apache.org/jira/browse/Hbase-4416

  --- This failure in fact is fixed by

https://issues.apache.org/jira/browse/HBASE-4540

1. Symptom

HMaster crashes after OpenedRegionHandler detects a dead region ZK.

1.1 Severity

Critical

1.2 Was there exception thrown?

Yes

1.2.1 Were there multiple exceptions?

Yes:

1. RS1 dies

2. HMaster cannot delete RS1 when assign opened region

3. HMaster aborted

1.3 Scope of the failure

Entire cluster

2. How to reproduce this failure

2.0 Version

0.90.4

2.1 Configuration

Standard

2.2 Reproduction procedure

1. Master balances region R from RS1 to RS2 (feature start, long running)

1.1 RS1 reports OPENED of R

1.2 Master queues a OpenedRegionHandler for R@RS1

2. RS1 dies (disconnect)

2.1 Master processes the splits and reassigns R to RS2

2.2 RS2 reports OPENED of R

2.3 Master queues a OpenedRegionHandler for R@RS2

2.4 OpenedRegionHandler for R@RS1 is finally processed, but leaves the region in a weird state (log #1)

2.5 OpenedRegionHandler for R@RS2 is processed, fails when it tries to delete the znode, kills the master (log #2)

Log 1:

2011-09-15 01:57:47,430 INFO org.apache.hadoop.hbase.master.AssignmentManager: The server is not in online servers, ServerName=sv4r23s44,60020,1316076811761, region=6e22b45f4288ea4d73f612ccf111aea6

2011-09-15 01:57:47,430 DEBUG org.apache.hadoop.hbase.master.handler.OpenedRegionHandler: Opened region 6e22b45f4288ea4d73f612ccf111aea6 on sv4r23s44,60020,1316076811761

Log 2:

2011-09-15 01:58:10,171 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:60000-0x231d7b21aba0480 Deleting existing unassigned node for 6e22b45f4288ea4d73f612ccf111aea6 that is in expected state RS_ZK_REGION_OPENED

2011-09-15 01:58:10,204 DEBUG org.apache.hadoop.hbase.zookeeper.ZKUtil: master:60000-0x231d7b21aba0480 Unable to get data of znode /hbase/unassigned/6e22b45f4288ea4d73f612ccf111aea6 because node does not exist (not necessarily an error)

2011-09-15 01:58:10,204 FATAL org.apache.hadoop.hbase.master.HMaster: Error deleting OPENED node in ZK for transition ZK node (6e22b45f4288ea4d73f612ccf111aea6)

2.2.1 Timing order

In this order

2.2.2 Events order externally controllable?

No (multi-node): RS1 must die when RS1 reports OPENED to master and OpenedRegionHander for R@RS1 hasn’t been processed by Master.

2.3 Can the logs tell how to reproduce the failure?

Yes

2.4 How many machines needed?

3. Master, RS1, RS2

3. Diagnosis procedure

3.1 Detailed Symptom (where you start)

The log messages above.

3.2 Backward inference

Locating the code printing the fatal msg: hbase.master.handler.OpenedRegionHandler.java:

  public void process() {

    LOG.debug("Handling OPENED event for " + this.regionInfo.getEncodedName() +

      "; deleting unassigned node");

    // Remove region from in-memory transition and unassigned node from ZK

    try {

      ZKAssign.deleteOpenedNode(server.getZooKeeper(),

          regionInfo.getEncodedName());

    } catch (KeeperException e) {

      server.abort("Error deleting OPENED node in ZK for transition ZK node (" +

          regionInfo.getEncodedName() + ")", e);

    }

    // Code to defend against case where we get SPLIT before region open

    // processing completes; temporary till we make SPLITs go via zk -- 0.92.

    if (this.assignmentManager.isRegionInTransition(regionInfo) != null) {

      this.assignmentManager.regionOnline(regionInfo, serverInfo);

    } else {

      LOG.warn("Skipping the onlining of " + regionInfo.getRegionNameAsString() +

        " because regions is NOT in RIT -- presuming this is because it SPLIT");

    }

So it failed to deleted the Opened node in ZK. We locate the other error msg:

 public void regionOnline(HRegionInfo regionInfo, HServerInfo serverInfo) {

    synchronized (this.regions) {

      // Add check

      .. ..

      if (isServerOnline(hsiWithoutLoad.getServerName())) {

        this.regions.put(regionInfo, hsiWithoutLoad);

        addToServers(hsiWithoutLoad, regionInfo);

        this.regions.notifyAll();

      } else {

        LOG.info("The server is not in online servers, ServerName=" +

          hsiWithoutLoad.getServerName() + ", region=" +

          regionInfo.getEncodedName());

      }

    }

    .. ..

So here the picture is clear:

This region has been deleted twice in OpenedRegionHandler from ZK: the first time deleted because of it was opened by RS1 (which later died), and the 2nd time was deleted because it was later opened by RS2. The 2nd time it failed the delete because the region info has already been deleted the first time.

4. Root cause

HMaster’s OpenedRegionHandler should blindly delete twice. The 2nd time it didn’t handle the error correctly.

4.1 Category:

Incorrect error handling (handled, statement coverage)

In fact, this piece of code:

    try {

      ZKAssign.deleteOpenedNode(server.getZooKeeper(),

          regionInfo.getEncodedName());

    } catch (KeeperException e) {

      server.abort("Error deleting OPENED node in ZK for transition ZK node (" +

          regionInfo.getEncodedName() + ")", e);

    }

Is completely wrong: in the fix they made sure this error do not bring down the entire cluster!

5. Fix

5.1 How?

   public void process() {

-    debugLog(regionInfo, "Handling OPENED event for " + this.regionInfo.getEncodedName() +

-      "; deleting unassigned node");

-    // Remove region from in-memory transition and unassigned node from ZK

-    try {

-      ZKAssign.deleteOpenedNode(server.getZooKeeper(),

-          regionInfo.getEncodedName());

-    } catch (KeeperException e) {

-      server.abort("Error deleting OPENED node in ZK for transition ZK node (" +

-          regionInfo.getEncodedName() + ")", e);

-    }

-    // Code to defend against case where we get SPLIT before region open

-    // processing completes; temporary till we make SPLITs go via zk -- 0.92.

-    if (this.assignmentManager.isRegionInTransition(regionInfo) != null) {

-      this.assignmentManager.regionOnline(regionInfo, serverInfo);

+    RegionState regionState = this.assignmentManager.isRegionInTransition(regionInfo);

+    if (regionState != null

+        && regionState.getState().equals(RegionState.State.OPEN)) {

+      if (deleteOpenedNode(expectedVersion)) {

+        // Remove region from in-memory transition and unassigned node from ZK

+        this.assignmentManager.regionOnline(regionInfo, this.serverInfo);

+        debugLog(regionInfo, "The master has opened the region " +

+            regionInfo.getRegionNameAsString() + " that was online on " +

+            this.serverInfo.toString());

+      } else {

+        LOG.error("The znode of region " + regionInfo.getRegionNameAsString() +

+          " could not be deleted.");

+      }