HBase
  1. HBase
  2. HBASE-2707

Can't recover from a dead ROOT server if any exceptions happens during log splitting

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 0.90.0
    • Component/s: None
    • Labels:
      None
    • Hadoop Flags:
      Reviewed

      Description

      There's an almost easy way to get stuck after a RS holding ROOT dies, usually from a GC-like event. It happens frequently to my TestReplication in HBASE-2223.

      Some logs:

      2010-06-10 11:35:52,090 INFO  [master] wal.HLog(1175): Spliting is done. Removing old log dir hdfs://localhost:55814/user/jdcryans/.logs/10.10.1.63,55846,1276194933831
      2010-06-10 11:35:52,095 WARN  [master] master.RegionServerOperationQueue(183): Failed processing: ProcessServerShutdown of 10.10.1.63,55846,1276194933831; putting onto delayed todo queue
      java.io.IOException: Cannot delete: hdfs://localhost:55814/user/jdcryans/.logs/10.10.1.63,55846,1276194933831
              at org.apache.hadoop.hbase.regionserver.wal.HLog.splitLog(HLog.java:1179)
              at org.apache.hadoop.hbase.master.ProcessServerShutdown.process(ProcessServerShutdown.java:298)
              at org.apache.hadoop.hbase.master.RegionServerOperationQueue.process(RegionServerOperationQueue.java:149)
              at org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:456)
      Caused by: java.io.IOException: java.io.IOException: /user/jdcryans/.logs/10.10.1.63,55846,1276194933831 is non empty
      2010-06-10 11:35:52,097 DEBUG [master] master.RegionServerOperationQueue(126): -ROOT- isn't online, can't process delayedToDoQueue items
      2010-06-10 11:35:53,098 DEBUG [master] master.RegionServerOperationQueue(126): -ROOT- isn't online, can't process delayedToDoQueue items
      2010-06-10 11:35:53,523 INFO  [main.serverMonitor] master.ServerManager$ServerMonitor(131): 1 region servers, 1 dead, average load 14.0[10.10.1.63,55846,1276194933831]
      2010-06-10 11:35:54,099 DEBUG [master] master.RegionServerOperationQueue(126): -ROOT- isn't online, can't process delayedToDoQueue items
      2010-06-10 11:35:55,101 DEBUG [master] master.RegionServerOperationQueue(126): -ROOT- isn't online, can't process delayedToDoQueue items
      

      The last lines are my own debug. Since we don't process the delayed todo if ROOT isn't online, we'll never reassign the regions.

      1. 2707-0.20.txt
        1 kB
        stack
      2. 2707-test.txt
        13 kB
        stack
      3. HBASE-2707.patch
        2 kB
        Jean-Daniel Cryans

        Issue Links

          Activity

          Hide
          Jean-Daniel Cryans added a comment -

          Stack and I talked a lot about it, here's what we came up with. It's very hard for me to come up with a unit test since it's all deep in the master and very much time-based, but I tested the patch with TestReplication a lot and 1) it doesn't fail anymore and 2) I see in the logs that the master does the right thing.

          Should I commit this?

          Show
          Jean-Daniel Cryans added a comment - Stack and I talked a lot about it, here's what we came up with. It's very hard for me to come up with a unit test since it's all deep in the master and very much time-based, but I tested the patch with TestReplication a lot and 1) it doesn't fail anymore and 2) I see in the logs that the master does the right thing. Should I commit this?
          Hide
          stack added a comment -

          I think we need a test for this because i can't see how ROOT is recovered if the code in processervershutdown#process is like this:

              if (!rootRescanned) {
                // Scan the ROOT region
                Boolean result = new ScanRootRegion(
                    new MetaRegion(master.getRegionManager().getRootRegionLocation(),
                        HRegionInfo.ROOT_REGIONINFO), this.master).doWithRetries();
                if (result == null) {
                  // Master is closing - give up
                  return true;
                }
          
                if (LOG.isDebugEnabled()) {
                  LOG.debug("Process server shutdown scanning root region on " +
                    master.getRegionManager().getRootRegionLocation().getBindAddress() +
                    " finished " + Thread.currentThread().getName());
                }
                rootRescanned = true;
              }
          

          If the current server being processed held the ROOT and the first thing we do processing a shutdown of a server that held root is to clear the root location, how is the above code succeeding?

          Assigning myself to mess w/ a test.

          Show
          stack added a comment - I think we need a test for this because i can't see how ROOT is recovered if the code in processervershutdown#process is like this: if (!rootRescanned) { // Scan the ROOT region Boolean result = new ScanRootRegion( new MetaRegion(master.getRegionManager().getRootRegionLocation(), HRegionInfo.ROOT_REGIONINFO), this .master).doWithRetries(); if (result == null ) { // Master is closing - give up return true ; } if (LOG.isDebugEnabled()) { LOG.debug( " Process server shutdown scanning root region on " + master.getRegionManager().getRootRegionLocation().getBindAddress() + " finished " + Thread .currentThread().getName()); } rootRescanned = true ; } If the current server being processed held the ROOT and the first thing we do processing a shutdown of a server that held root is to clear the root location, how is the above code succeeding? Assigning myself to mess w/ a test.
          Hide
          stack added a comment -

          Oh, regards the patch, I think it definetly an improvement over what was there before (what was there before was silly – it made this bug that J-D filed).

          Show
          stack added a comment - Oh, regards the patch, I think it definetly an improvement over what was there before (what was there before was silly – it made this bug that J-D filed).
          Hide
          Jean-Daniel Cryans added a comment -

          I'm marking this a as blocker for HBASE-2223, my test fails sometimes without the patch. Also I must have ran my test with this patch almost 40 times (I'm almost always running it) and I never got any issue.

          Show
          Jean-Daniel Cryans added a comment - I'm marking this a as blocker for HBASE-2223 , my test fails sometimes without the patch. Also I must have ran my test with this patch almost 40 times (I'm almost always running it) and I never got any issue.
          Hide
          Jean-Daniel Cryans added a comment -

          So actually the code of process is looks like:

          LOG.info("Log split complete, meta reassignment and scanning:");
              if (this.isRootServer) {
                LOG.info("ProcessServerShutdown reassigning ROOT region");
                master.getRegionManager().reassignRootRegion();
                isRootServer = false;  // prevent double reassignment... heh.
              }
          
              for (MetaRegion metaRegion : metaRegions) {
                LOG.info("ProcessServerShutdown setting to unassigned: " + metaRegion.toString());
                master.getRegionManager().setUnassigned(metaRegion.getRegionInfo(), true);
              }
              // one the meta regions are online, "forget" about them.  Since there are explicit
              // checks below to make sure meta/root are online, this is likely to occur.
              metaRegions.clear();
          
              if (!rootAvailable()) {
                // Return true so that worker does not put this request back on the
                // toDoQueue.
                // rootAvailable() has already put it on the delayedToDoQueue
                return true;
              }
          
              if (!rootRescanned) {
                // Scan the ROOT region
                Boolean result = new ScanRootRegion(
                    new MetaRegion(master.getRegionManager().getRootRegionLocation(),
                        HRegionInfo.ROOT_REGIONINFO), this.master).doWithRetries();
                if (result == null) {
                  // Master is closing - give up
                  return true;
                }
          
                if (LOG.isDebugEnabled()) {
                  LOG.debug("Process server shutdown scanning root region on " +
                    master.getRegionManager().getRootRegionLocation().getBindAddress() +
                    " finished " + Thread.currentThread().getName());
                }
                rootRescanned = true;
              }
          

          So if the RS had ROOT, it will be reassigned right away and then the method returns if !rootAvailable. Later when we come back and root was assigned, process server shutdown will finish its job. This is how the code you pasted succeeds.

          Show
          Jean-Daniel Cryans added a comment - So actually the code of process is looks like: LOG.info( "Log split complete, meta reassignment and scanning:" ); if ( this .isRootServer) { LOG.info( "ProcessServerShutdown reassigning ROOT region" ); master.getRegionManager().reassignRootRegion(); isRootServer = false ; // prevent double reassignment... heh. } for (MetaRegion metaRegion : metaRegions) { LOG.info( "ProcessServerShutdown setting to unassigned: " + metaRegion.toString()); master.getRegionManager().setUnassigned(metaRegion.getRegionInfo(), true ); } // one the meta regions are online, "forget" about them. Since there are explicit // checks below to make sure meta/root are online, this is likely to occur. metaRegions.clear(); if (!rootAvailable()) { // Return true so that worker does not put this request back on the // toDoQueue. // rootAvailable() has already put it on the delayedToDoQueue return true ; } if (!rootRescanned) { // Scan the ROOT region Boolean result = new ScanRootRegion( new MetaRegion(master.getRegionManager().getRootRegionLocation(), HRegionInfo.ROOT_REGIONINFO), this .master).doWithRetries(); if (result == null ) { // Master is closing - give up return true ; } if (LOG.isDebugEnabled()) { LOG.debug( " Process server shutdown scanning root region on " + master.getRegionManager().getRootRegionLocation().getBindAddress() + " finished " + Thread .currentThread().getName()); } rootRescanned = true ; } So if the RS had ROOT , it will be reassigned right away and then the method returns if !rootAvailable. Later when we come back and root was assigned, process server shutdown will finish its job. This is how the code you pasted succeeds.
          Hide
          stack added a comment -

          So its broken then? We assign ROOT but don't recover its edits?

          Show
          stack added a comment - So its broken then? We assign ROOT but don't recover its edits?
          Hide
          stack added a comment -

          Hmm... chatted with J-D and he points out that the above runs AFTER logs are split so I had it incorrect. Above should be good.

          Show
          stack added a comment - Hmm... chatted with J-D and he points out that the above runs AFTER logs are split so I had it incorrect. Above should be good.
          Hide
          stack added a comment -

          Test that puts off the processing of the shutdown of the server that was carrying root. This test never completes. With the patch in place, it does.

          Show
          stack added a comment - Test that puts off the processing of the shutdown of the server that was carrying root. This test never completes. With the patch in place, it does.
          Hide
          Jean-Daniel Cryans added a comment -

          +1 but minor nit, why isn't DELAY private?

          Show
          Jean-Daniel Cryans added a comment - +1 but minor nit, why isn't DELAY private?
          Hide
          stack added a comment -

          Committed. Thanks for review J-D (I removed DELAY altogether).

          Show
          stack added a comment - Committed. Thanks for review J-D (I removed DELAY altogether).
          Hide
          stack added a comment -

          Backport to 0.20. Please review. I'd like this to go into 0.20 since it hoses cluster if it ever happens.

          Show
          stack added a comment - Backport to 0.20. Please review. I'd like this to go into 0.20 since it hoses cluster if it ever happens.
          Hide
          stack added a comment -

          Moving into 0.20.6.

          Show
          stack added a comment - Moving into 0.20.6.
          Hide
          stack added a comment -

          Taking out of 0.20.6. Open separate issue. The attached 0.20 patch is not enough. The change would be more major than this patch presumes.

          Show
          stack added a comment - Taking out of 0.20.6. Open separate issue. The attached 0.20 patch is not enough. The change would be more major than this patch presumes.
          Hide
          stack added a comment -

          Latest iteration. What is currently in place is currently broke it turns out. More on this later.

          Show
          stack added a comment - Latest iteration. What is currently in place is currently broke it turns out. More on this later.

            People

            • Assignee:
              stack
              Reporter:
              Jean-Daniel Cryans
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development