From 8fdc5bdb2ac551183a24094ee8b13f565ba125b7 Mon Sep 17 00:00:00 2001 From: tedyu Date: Tue, 10 Feb 2015 08:54:43 -0800 Subject: [PATCH] HBASE-13004 Make possible to explain why HBaseTestingUtility.waitFor fails (Andrey Stepachev) --- .../java/org/apache/hadoop/hbase/Waiter.java | 36 +++- .../hadoop/hbase/HBaseTestingUtility.java | 170 +++++++++++++----- .../security/access/TestAccessController.java | 8 +- .../hbase/snapshot/SnapshotTestingUtils.java | 8 +- 4 files changed, 162 insertions(+), 60 deletions(-) diff --git a/hbase-common/src/test/java/org/apache/hadoop/hbase/Waiter.java b/hbase-common/src/test/java/org/apache/hadoop/hbase/Waiter.java index 468333ddd39..9e72ddb6352 100644 --- a/hbase-common/src/test/java/org/apache/hadoop/hbase/Waiter.java +++ b/hbase-common/src/test/java/org/apache/hadoop/hbase/Waiter.java @@ -97,6 +97,21 @@ public final class Waiter { } + /** + * A mixin interface, can be used with {@link Waiter} to explain failed state. + */ + @InterfaceAudience.Private + public interface ExplainingPredicate extends Predicate { + + /** + * Perform a predicate evaluation. + * + * @return explanation of failed state + */ + String explainFailure() throws E; + + } + /** * Makes the current thread sleep for the duration equal to the specified time in milliseconds * multiplied by the {@link #getWaitForRatio(Configuration)}. @@ -190,9 +205,13 @@ public final class Waiter { LOG.warn(MessageFormat.format("Waiting interrupted after [{0}] msec", System.currentTimeMillis() - started)); } else if (failIfTimeout) { - Assert.fail(MessageFormat.format("Waiting timed out after [{0}] msec", adjustedTimeout)); + String msg = getExplanation(predicate); + Assert.fail(MessageFormat + .format("Waiting timed out after [{0}] msec" + msg, adjustedTimeout)); } else { - LOG.warn(MessageFormat.format("Waiting timed out after [{0}] msec", adjustedTimeout)); + String msg = getExplanation(predicate); + LOG.warn( + MessageFormat.format("Waiting timed out after [{0}] msec" + msg, adjustedTimeout)); } } return (eval || interrupted) ? (System.currentTimeMillis() - started) : -1; @@ -201,4 +220,17 @@ public final class Waiter { } } + public static String getExplanation(Predicate explain) { + if (explain instanceof ExplainingPredicate) { + try { + return " " + ((ExplainingPredicate) explain).explainFailure(); + } catch (Exception e) { + LOG.error("Failed to get explanation, ", e); + return e.getMessage(); + } + } else { + return ""; + } + } + } diff --git a/hbase-server/src/test/java/org/apache/hadoop/hbase/HBaseTestingUtility.java b/hbase-server/src/test/java/org/apache/hadoop/hbase/HBaseTestingUtility.java index 9ed121ddfb7..1eef9671863 100644 --- a/hbase-server/src/test/java/org/apache/hadoop/hbase/HBaseTestingUtility.java +++ b/hbase-server/src/test/java/org/apache/hadoop/hbase/HBaseTestingUtility.java @@ -17,10 +17,6 @@ */ package org.apache.hadoop.hbase; -import static org.junit.Assert.assertEquals; -import static org.junit.Assert.assertTrue; -import static org.junit.Assert.fail; - import java.io.File; import java.io.IOException; import java.io.OutputStream; @@ -52,6 +48,7 @@ import org.apache.commons.logging.impl.Log4JLogger; import org.apache.hadoop.conf.Configuration; import org.apache.hadoop.fs.FileSystem; import org.apache.hadoop.fs.Path; +import org.apache.hadoop.hbase.Waiter.ExplainingPredicate; import org.apache.hadoop.hbase.Waiter.Predicate; import org.apache.hadoop.hbase.classification.InterfaceAudience; import org.apache.hadoop.hbase.classification.InterfaceStability; @@ -64,7 +61,6 @@ import org.apache.hadoop.hbase.client.Get; import org.apache.hadoop.hbase.client.HBaseAdmin; import org.apache.hadoop.hbase.client.HConnection; import org.apache.hadoop.hbase.client.HTable; -import org.apache.hadoop.hbase.client.HTableInterface; import org.apache.hadoop.hbase.client.Put; import org.apache.hadoop.hbase.client.RegionLocator; import org.apache.hadoop.hbase.client.Result; @@ -122,6 +118,10 @@ import org.apache.zookeeper.WatchedEvent; import org.apache.zookeeper.ZooKeeper; import org.apache.zookeeper.ZooKeeper.States; +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertTrue; +import static org.junit.Assert.fail; + /** * Facility for testing HBase. Replacement for * old HBaseTestCase and HBaseClusterTestCase functionality. @@ -2808,12 +2808,54 @@ public class HBaseTestingUtility extends HBaseCommonTestingUtility { */ public void waitTableAvailable(TableName table) throws InterruptedException, IOException { - waitTableAvailable(getHBaseAdmin(), table.getName(), 30000); + waitTableAvailable(table.getName(), 30000); } - public void waitTableAvailable(Admin admin, byte[] table) + public void waitTableAvailable(TableName table, long timeoutMillis) throws InterruptedException, IOException { - waitTableAvailable(admin, table, 30000); + waitFor(timeoutMillis, predicateTableAvailable(table)); + } + + public String explainTableAvailability(TableName tableName) throws IOException { + String msg = explainTableState(tableName) + ","; + if (getHBaseCluster().getMaster().isAlive()) { + Map assignments = + getHBaseCluster().getMaster().getAssignmentManager().getRegionStates() + .getRegionAssignments(); + final List> metaLocations = + MetaTableAccessor + .getTableRegionsAndLocations(getZooKeeperWatcher(), connection, tableName); + for (Pair metaLocation : metaLocations) { + HRegionInfo hri = metaLocation.getFirst(); + ServerName sn = metaLocation.getSecond(); + if (!assignments.containsKey(hri)) { + msg += ", region " + hri + + " not assigned, but found in meta, it expected to be on " + sn; + + } else if (sn == null) { + msg += ", region " + hri + + " assigned, but has no server in meta"; + } else if (!sn.equals(assignments.get(hri))) { + msg += ", region " + hri + + " assigned, but has different servers in meta and AM ( " + + sn + " <> " + assignments.get(hri); + } + } + } + return msg; + } + + public String explainTableState(TableName tableName) throws IOException { + try { + if (getHBaseAdmin().isTableEnabled(tableName)) + return "table enabled in zk"; + else if (getHBaseAdmin().isTableDisabled(tableName)) + return "table disabled in zk"; + else + return "table in uknown state"; + } catch (TableNotFoundException e) { + return "table not exists"; + } } /** @@ -2850,12 +2892,7 @@ public class HBaseTestingUtility extends HBaseCommonTestingUtility { */ public void waitTableEnabled(TableName table) throws InterruptedException, IOException { - waitTableEnabled(getHBaseAdmin(), table.getName(), 30000); - } - - public void waitTableEnabled(Admin admin, byte[] table) - throws InterruptedException, IOException { - waitTableEnabled(admin, table, 30000); + waitTableEnabled(table, 30000); } /** @@ -2869,30 +2906,12 @@ public class HBaseTestingUtility extends HBaseCommonTestingUtility { */ public void waitTableEnabled(byte[] table, long timeoutMillis) throws InterruptedException, IOException { - waitTableEnabled(getHBaseAdmin(), table, timeoutMillis); + waitTableEnabled(TableName.valueOf(table), timeoutMillis); } - public void waitTableEnabled(Admin admin, byte[] table, long timeoutMillis) - throws InterruptedException, IOException { - TableName tableName = TableName.valueOf(table); - long startWait = System.currentTimeMillis(); - waitTableAvailable(admin, table, timeoutMillis); - while (!admin.isTableEnabled(tableName)) { - assertTrue("Timed out waiting for table to become available and enabled " + - Bytes.toStringBinary(table), - System.currentTimeMillis() - startWait < timeoutMillis); - Thread.sleep(200); - } - // Finally make sure all regions are fully open and online out on the cluster. Regions may be - // in the hbase:meta table and almost open on all regionservers but there setting the region - // online in the regionserver is the very last thing done and can take a little while to happen. - // Below we do a get. The get will retry if a NotServeringRegionException or a - // RegionOpeningException. It is crass but when done all will be online. - try { - Canary.sniff(admin, tableName); - } catch (Exception e) { - throw new IOException(e); - } + public void waitTableEnabled(TableName table, long timeoutMillis) + throws IOException { + waitFor(timeoutMillis, predicateTableEnabled(table)); } /** @@ -3109,7 +3128,7 @@ public class HBaseTestingUtility extends HBaseCommonTestingUtility { try { Result r; while ((r = s.next()) != null) { - byte [] b = r.getValue(HConstants.CATALOG_FAMILY, HConstants.REGIONINFO_QUALIFIER); + byte[] b = r.getValue(HConstants.CATALOG_FAMILY, HConstants.REGIONINFO_QUALIFIER); HRegionInfo info = HRegionInfo.parseFromOrNull(b); if (info != null && info.getTable().equals(tableName)) { b = r.getValue(HConstants.CATALOG_FAMILY, HConstants.SERVER_QUALIFIER); @@ -3132,7 +3151,12 @@ public class HBaseTestingUtility extends HBaseCommonTestingUtility { // returing -- sometimes this can lag. HMaster master = getHBaseCluster().getMaster(); final RegionStates states = master.getAssignmentManager().getRegionStates(); - waitFor(timeout, 200, new Predicate() { + waitFor(timeout, 200, new ExplainingPredicate() { + @Override + public String explainFailure() throws IOException { + return explainTableAvailability(tableName); + } + @Override public boolean evaluate() throws IOException { List hris = states.getRegionsOfTable(tableName); @@ -3633,10 +3657,17 @@ public class HBaseTestingUtility extends HBaseCommonTestingUtility { /** * Returns a {@link Predicate} for checking that there are no regions in transition in master */ - public Waiter.Predicate predicateNoRegionsInTransition() { - return new Waiter.Predicate() { + public ExplainingPredicate predicateNoRegionsInTransition() { + return new ExplainingPredicate() { @Override - public boolean evaluate() throws Exception { + public String explainFailure() throws IOException { + final RegionStates regionStates = getMiniHBaseCluster().getMaster() + .getAssignmentManager().getRegionStates(); + return "found in transition: " + regionStates.getRegionsInTransition().toString(); + } + + @Override + public boolean evaluate() throws IOException { final RegionStates regionStates = getMiniHBaseCluster().getMaster() .getAssignmentManager().getRegionStates(); return !regionStates.isRegionsInTransition(); @@ -3647,11 +3678,58 @@ public class HBaseTestingUtility extends HBaseCommonTestingUtility { /** * Returns a {@link Predicate} for checking that table is enabled */ - public Waiter.Predicate predicateTableEnabled(final TableName tableName) { - return new Waiter.Predicate() { - @Override - public boolean evaluate() throws Exception { - return getHBaseAdmin().isTableEnabled(tableName); + public Waiter.Predicate predicateTableEnabled(final TableName tableName) { + return new ExplainingPredicate() { + @Override + public String explainFailure() throws IOException { + return explainTableState(tableName); + } + + @Override + public boolean evaluate() throws IOException { + return getHBaseAdmin().tableExists(tableName) && getHBaseAdmin().isTableEnabled(tableName); + } + }; + } + + /** + * Returns a {@link Predicate} for checking that table is enabled + */ + public Waiter.Predicate predicateTableDisabled(final TableName tableName) { + return new ExplainingPredicate() { + @Override + public String explainFailure() throws IOException { + return explainTableState(tableName); + } + + @Override + public boolean evaluate() throws IOException { + return getHBaseAdmin().isTableDisabled(tableName); + } + }; + } + + /** + * Returns a {@link Predicate} for checking that table is enabled + */ + public Waiter.Predicate predicateTableAvailable(final TableName tableName) { + return new ExplainingPredicate() { + @Override + public String explainFailure() throws IOException { + return explainTableAvailability(tableName); + } + + @Override + public boolean evaluate() throws IOException { + boolean tableAvailable = getHBaseAdmin().isTableAvailable(tableName); + if (tableAvailable) { + try { + Canary.sniff(getHBaseAdmin(), tableName); + } catch (Exception e) { + throw new IOException("Canary sniff failed for table " + tableName, e); + } + } + return tableAvailable; } }; } diff --git a/hbase-server/src/test/java/org/apache/hadoop/hbase/security/access/TestAccessController.java b/hbase-server/src/test/java/org/apache/hadoop/hbase/security/access/TestAccessController.java index cdc87e5e8e8..138e6ffd8f6 100644 --- a/hbase-server/src/test/java/org/apache/hadoop/hbase/security/access/TestAccessController.java +++ b/hbase-server/src/test/java/org/apache/hadoop/hbase/security/access/TestAccessController.java @@ -924,11 +924,9 @@ public class TestAccessController extends SecureTestUtil { setPermission(loadPath, FsPermission.valueOf("-rwxrwxrwx")); try (HTable table = (HTable)TEST_UTIL.getConnection().getTable(tableName)) { - try (Admin admin = TEST_UTIL.getHBaseAdmin()) { - TEST_UTIL.waitTableEnabled(admin, tableName.getName()); - LoadIncrementalHFiles loader = new LoadIncrementalHFiles(conf); - loader.doBulkLoad(loadPath, table); - } + TEST_UTIL.waitTableEnabled(tableName); + LoadIncrementalHFiles loader = new LoadIncrementalHFiles(conf); + loader.doBulkLoad(loadPath, table); } } diff --git a/hbase-server/src/test/java/org/apache/hadoop/hbase/snapshot/SnapshotTestingUtils.java b/hbase-server/src/test/java/org/apache/hadoop/hbase/snapshot/SnapshotTestingUtils.java index e5f91d7c14d..c8abff014c2 100644 --- a/hbase-server/src/test/java/org/apache/hadoop/hbase/snapshot/SnapshotTestingUtils.java +++ b/hbase-server/src/test/java/org/apache/hadoop/hbase/snapshot/SnapshotTestingUtils.java @@ -632,13 +632,7 @@ public class SnapshotTestingUtils { region.waitForFlushesAndCompactions(); } // Wait up to 60 seconds for a table to be available. - final HBaseAdmin hBaseAdmin = util.getHBaseAdmin(); - util.waitFor(60000, new Waiter.Predicate() { - @Override - public boolean evaluate() throws IOException { - return hBaseAdmin.isTableAvailable(tableName); - } - }); + util.waitFor(60000, util.predicateTableAvailable(tableName)); } public static void createTable(final HBaseTestingUtility util, final TableName tableName,