001/* 002 * Licensed to the Apache Software Foundation (ASF) under one 003 * or more contributor license agreements. See the NOTICE file 004 * distributed with this work for additional information 005 * regarding copyright ownership. The ASF licenses this file 006 * to you under the Apache License, Version 2.0 (the 007 * "License"); you may not use this file except in compliance 008 * with the License. You may obtain a copy of the License at 009 * 010 * http://www.apache.org/licenses/LICENSE-2.0 011 * 012 * Unless required by applicable law or agreed to in writing, software 013 * distributed under the License is distributed on an "AS IS" BASIS, 014 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 015 * See the License for the specific language governing permissions and 016 * limitations under the License. 017 */ 018package org.apache.hadoop.hbase.master; 019 020import static org.apache.hadoop.hbase.HConstants.HBASE_SPLIT_WAL_MAX_SPLITTER; 021import static org.apache.hadoop.hbase.SplitLogCounters.tot_mgr_wait_for_zk_delete; 022import static org.junit.jupiter.api.Assertions.assertEquals; 023import static org.junit.jupiter.api.Assertions.assertTrue; 024import static org.junit.jupiter.api.Assertions.fail; 025 026import java.io.IOException; 027import java.util.ArrayList; 028import java.util.Arrays; 029import java.util.Iterator; 030import java.util.List; 031import java.util.NavigableSet; 032import java.util.concurrent.ExecutorService; 033import java.util.concurrent.Executors; 034import java.util.concurrent.Future; 035import java.util.concurrent.TimeUnit; 036import java.util.concurrent.TimeoutException; 037import java.util.concurrent.atomic.LongAdder; 038import org.apache.hadoop.conf.Configuration; 039import org.apache.hadoop.fs.FSDataOutputStream; 040import org.apache.hadoop.fs.FileSystem; 041import org.apache.hadoop.fs.Path; 042import org.apache.hadoop.hbase.HBaseTestingUtil; 043import org.apache.hadoop.hbase.HConstants; 044import org.apache.hadoop.hbase.KeyValue; 045import org.apache.hadoop.hbase.ServerName; 046import org.apache.hadoop.hbase.SingleProcessHBaseCluster; 047import org.apache.hadoop.hbase.SplitLogCounters; 048import org.apache.hadoop.hbase.StartTestingClusterOption; 049import org.apache.hadoop.hbase.TableName; 050import org.apache.hadoop.hbase.Waiter; 051import org.apache.hadoop.hbase.client.Put; 052import org.apache.hadoop.hbase.client.RegionInfo; 053import org.apache.hadoop.hbase.client.RegionInfoBuilder; 054import org.apache.hadoop.hbase.client.RegionLocator; 055import org.apache.hadoop.hbase.client.Table; 056import org.apache.hadoop.hbase.coordination.ZKSplitLogManagerCoordination; 057import org.apache.hadoop.hbase.master.assignment.RegionStates; 058import org.apache.hadoop.hbase.regionserver.HRegion; 059import org.apache.hadoop.hbase.regionserver.HRegionServer; 060import org.apache.hadoop.hbase.regionserver.MultiVersionConcurrencyControl; 061import org.apache.hadoop.hbase.regionserver.Region; 062import org.apache.hadoop.hbase.util.Bytes; 063import org.apache.hadoop.hbase.util.CommonFSUtils; 064import org.apache.hadoop.hbase.util.EnvironmentEdgeManager; 065import org.apache.hadoop.hbase.util.JVMClusterUtil.MasterThread; 066import org.apache.hadoop.hbase.util.JVMClusterUtil.RegionServerThread; 067import org.apache.hadoop.hbase.util.Threads; 068import org.apache.hadoop.hbase.wal.WAL; 069import org.apache.hadoop.hbase.wal.WALEdit; 070import org.apache.hadoop.hbase.wal.WALEditInternalHelper; 071import org.apache.hadoop.hbase.wal.WALKeyImpl; 072import org.apache.hadoop.hbase.zookeeper.ZKUtil; 073import org.junit.jupiter.api.AfterAll; 074import org.junit.jupiter.api.AfterEach; 075import org.junit.jupiter.api.BeforeAll; 076import org.junit.jupiter.api.BeforeEach; 077import org.junit.jupiter.api.Test; 078import org.junit.jupiter.api.TestInfo; 079import org.slf4j.Logger; 080import org.slf4j.LoggerFactory; 081 082import org.apache.hadoop.hbase.shaded.protobuf.ProtobufUtil; 083 084/** 085 * Base class for testing distributed log splitting. 086 */ 087public abstract class AbstractTestDLS { 088 private static final Logger LOG = LoggerFactory.getLogger(AbstractTestDLS.class); 089 090 private static final HBaseTestingUtil TEST_UTIL = new HBaseTestingUtil(); 091 092 // Start a cluster with 2 masters and 5 regionservers 093 private static final int NUM_MASTERS = 2; 094 private static final int NUM_RS = 5; 095 private static byte[] COLUMN_FAMILY = Bytes.toBytes("family"); 096 097 private TableName tableName; 098 private SingleProcessHBaseCluster cluster; 099 private HMaster master; 100 private Configuration conf; 101 102 @BeforeAll 103 public static void setup() throws Exception { 104 // Uncomment the following line if more verbosity is needed for 105 // debugging (see HBASE-12285 for details). 106 // Logger.getLogger("org.apache.hadoop.hbase").setLevel(Level.DEBUG); 107 TEST_UTIL.startMiniZKCluster(); 108 TEST_UTIL.startMiniDFSCluster(3); 109 } 110 111 @AfterAll 112 public static void tearDown() throws Exception { 113 TEST_UTIL.shutdownMiniCluster(); 114 } 115 116 protected abstract String getWalProvider(); 117 118 private void startCluster(int numRS) throws Exception { 119 SplitLogCounters.resetCounters(); 120 LOG.info("Starting cluster"); 121 conf.setLong("hbase.splitlog.max.resubmit", 0); 122 // Make the failure test faster 123 conf.setInt("zookeeper.recovery.retry", 0); 124 conf.setInt(HConstants.REGIONSERVER_INFO_PORT, -1); 125 conf.setFloat(HConstants.LOAD_BALANCER_SLOP_KEY, (float) 100.0); // no load balancing 126 conf.setInt(HBASE_SPLIT_WAL_MAX_SPLITTER, 3); 127 conf.setInt(HConstants.REGION_SERVER_HIGH_PRIORITY_HANDLER_COUNT, 10); 128 conf.set("hbase.wal.provider", getWalProvider()); 129 StartTestingClusterOption option = 130 StartTestingClusterOption.builder().numMasters(NUM_MASTERS).numRegionServers(numRS).build(); 131 TEST_UTIL.startMiniHBaseCluster(option); 132 cluster = TEST_UTIL.getHBaseCluster(); 133 LOG.info("Waiting for active/ready master"); 134 cluster.waitForActiveAndReadyMaster(); 135 master = cluster.getMaster(); 136 TEST_UTIL.waitFor(120000, 200, new Waiter.Predicate<Exception>() { 137 @Override 138 public boolean evaluate() throws Exception { 139 return cluster.getLiveRegionServerThreads().size() >= numRS; 140 } 141 }); 142 } 143 144 @BeforeEach 145 public void before(TestInfo testInfo) throws Exception { 146 conf = TEST_UTIL.getConfiguration(); 147 tableName = TableName.valueOf(testInfo.getTestMethod().get().getName()); 148 } 149 150 @AfterEach 151 public void after() throws Exception { 152 TEST_UTIL.shutdownMiniHBaseCluster(); 153 TEST_UTIL.getTestFileSystem().delete(CommonFSUtils.getRootDir(TEST_UTIL.getConfiguration()), 154 true); 155 ZKUtil.deleteNodeRecursively(TEST_UTIL.getZooKeeperWatcher(), "/hbase"); 156 } 157 158 @Test 159 public void testMasterStartsUpWithLogSplittingWork() throws Exception { 160 conf.setInt(ServerManager.WAIT_ON_REGIONSERVERS_MINTOSTART, NUM_RS - 1); 161 startCluster(NUM_RS); 162 163 int numRegionsToCreate = 40; 164 int numLogLines = 1000; 165 // turn off load balancing to prevent regions from moving around otherwise 166 // they will consume recovered.edits 167 master.balanceSwitch(false); 168 169 try (Table ht = installTable(numRegionsToCreate)) { 170 HRegionServer hrs = findRSToKill(false); 171 List<RegionInfo> regions = ProtobufUtil.getOnlineRegions(hrs.getRSRpcServices()); 172 makeWAL(hrs, regions, numLogLines, 100); 173 174 // abort master 175 abortMaster(cluster); 176 177 // abort RS 178 LOG.info("Aborting region server: " + hrs.getServerName()); 179 hrs.abort("testing"); 180 181 // wait for abort completes 182 TEST_UTIL.waitFor(120000, 200, new Waiter.Predicate<Exception>() { 183 @Override 184 public boolean evaluate() throws Exception { 185 return cluster.getLiveRegionServerThreads().size() <= NUM_RS - 1; 186 } 187 }); 188 189 Thread.sleep(2000); 190 LOG.info("Current Open Regions:" + HBaseTestingUtil.getAllOnlineRegions(cluster).size()); 191 192 // wait for abort completes 193 TEST_UTIL.waitFor(120000, 200, new Waiter.Predicate<Exception>() { 194 @Override 195 public boolean evaluate() throws Exception { 196 return (HBaseTestingUtil.getAllOnlineRegions(cluster).size() >= (numRegionsToCreate + 1)); 197 } 198 }); 199 200 LOG.info("Current Open Regions After Master Node Starts Up:" 201 + HBaseTestingUtil.getAllOnlineRegions(cluster).size()); 202 203 assertEquals(numLogLines, TEST_UTIL.countRows(ht)); 204 } 205 } 206 207 @Test 208 public void testThreeRSAbort() throws Exception { 209 LOG.info("testThreeRSAbort"); 210 int numRegionsToCreate = 40; 211 int numRowsPerRegion = 100; 212 213 startCluster(NUM_RS); // NUM_RS=6. 214 215 try (Table table = installTable(numRegionsToCreate)) { 216 populateDataInTable(numRowsPerRegion); 217 218 List<RegionServerThread> rsts = cluster.getLiveRegionServerThreads(); 219 assertEquals(NUM_RS, rsts.size()); 220 cluster.killRegionServer(rsts.get(0).getRegionServer().getServerName()); 221 cluster.killRegionServer(rsts.get(1).getRegionServer().getServerName()); 222 cluster.killRegionServer(rsts.get(2).getRegionServer().getServerName()); 223 224 TEST_UTIL.waitFor(60000, new Waiter.ExplainingPredicate<Exception>() { 225 226 @Override 227 public boolean evaluate() throws Exception { 228 return cluster.getLiveRegionServerThreads().size() <= NUM_RS - 3; 229 } 230 231 @Override 232 public String explainFailure() throws Exception { 233 return "Timed out waiting for server aborts."; 234 } 235 }); 236 TEST_UTIL.waitUntilAllRegionsAssigned(tableName); 237 int rows; 238 try { 239 rows = TEST_UTIL.countRows(table); 240 } catch (Exception e) { 241 Threads.printThreadInfo(System.out, "Thread dump before fail"); 242 throw e; 243 } 244 assertEquals(numRegionsToCreate * numRowsPerRegion, rows); 245 } 246 } 247 248 @Test 249 public void testDelayedDeleteOnFailure() throws Exception { 250 if ( 251 !this.conf.getBoolean(HConstants.HBASE_SPLIT_WAL_COORDINATED_BY_ZK, 252 HConstants.DEFAULT_HBASE_SPLIT_COORDINATED_BY_ZK) 253 ) { 254 // This test depends on zk coordination.... 255 return; 256 } 257 LOG.info("testDelayedDeleteOnFailure"); 258 startCluster(1); 259 final SplitLogManager slm = master.getMasterWalManager().getSplitLogManager(); 260 final FileSystem fs = master.getMasterFileSystem().getFileSystem(); 261 final Path rootLogDir = 262 new Path(CommonFSUtils.getWALRootDir(conf), HConstants.HREGION_LOGDIR_NAME); 263 final Path logDir = new Path(rootLogDir, ServerName.valueOf("x", 1, 1).toString()); 264 fs.mkdirs(logDir); 265 ExecutorService executor = null; 266 try { 267 final Path corruptedLogFile = new Path(logDir, "x"); 268 FSDataOutputStream out; 269 out = fs.create(corruptedLogFile); 270 out.write(0); 271 out.write(Bytes.toBytes("corrupted bytes")); 272 out.close(); 273 ZKSplitLogManagerCoordination coordination = 274 (ZKSplitLogManagerCoordination) (master.getCoordinatedStateManager()) 275 .getSplitLogManagerCoordination(); 276 coordination.setIgnoreDeleteForTesting(true); 277 executor = Executors.newSingleThreadExecutor(); 278 Runnable runnable = new Runnable() { 279 @Override 280 public void run() { 281 try { 282 // since the logDir is a fake, corrupted one, so the split log worker 283 // will finish it quickly with error, and this call will fail and throw 284 // an IOException. 285 slm.splitLogDistributed(logDir); 286 } catch (IOException ioe) { 287 try { 288 assertTrue(fs.exists(corruptedLogFile)); 289 // this call will block waiting for the task to be removed from the 290 // tasks map which is not going to happen since ignoreZKDeleteForTesting 291 // is set to true, until it is interrupted. 292 slm.splitLogDistributed(logDir); 293 } catch (IOException e) { 294 assertTrue(Thread.currentThread().isInterrupted()); 295 return; 296 } 297 fail("did not get the expected IOException from the 2nd call"); 298 } 299 fail("did not get the expected IOException from the 1st call"); 300 } 301 }; 302 Future<?> result = executor.submit(runnable); 303 try { 304 result.get(2000, TimeUnit.MILLISECONDS); 305 } catch (TimeoutException te) { 306 // it is ok, expected. 307 } 308 waitForCounter(tot_mgr_wait_for_zk_delete, 0, 1, 10000); 309 executor.shutdownNow(); 310 executor = null; 311 312 // make sure the runnable is finished with no exception thrown. 313 result.get(); 314 } finally { 315 if (executor != null) { 316 // interrupt the thread in case the test fails in the middle. 317 // it has no effect if the thread is already terminated. 318 executor.shutdownNow(); 319 } 320 fs.delete(logDir, true); 321 } 322 } 323 324 private Table installTable(int nrs) throws Exception { 325 return installTable(nrs, 0); 326 } 327 328 private Table installTable(int nrs, int existingRegions) throws Exception { 329 // Create a table with regions 330 byte[] family = Bytes.toBytes("family"); 331 LOG.info("Creating table with " + nrs + " regions"); 332 Table table = TEST_UTIL.createMultiRegionTable(tableName, family, nrs); 333 int numRegions = -1; 334 try (RegionLocator r = TEST_UTIL.getConnection().getRegionLocator(tableName)) { 335 numRegions = r.getStartKeys().length; 336 } 337 assertEquals(nrs, numRegions); 338 LOG.info("Waiting for no more RIT\n"); 339 blockUntilNoRIT(); 340 // disable-enable cycle to get rid of table's dead regions left behind 341 // by createMultiRegions 342 assertTrue(TEST_UTIL.getAdmin().isTableEnabled(tableName)); 343 LOG.debug("Disabling table\n"); 344 TEST_UTIL.getAdmin().disableTable(tableName); 345 LOG.debug("Waiting for no more RIT\n"); 346 blockUntilNoRIT(); 347 NavigableSet<String> regions = HBaseTestingUtil.getAllOnlineRegions(cluster); 348 LOG.debug("Verifying only catalog region is assigned\n"); 349 if (regions.size() != 1) { 350 for (String oregion : regions) { 351 LOG.debug("Region still online: " + oregion); 352 } 353 } 354 assertEquals(1 + existingRegions, regions.size()); 355 LOG.debug("Enabling table\n"); 356 TEST_UTIL.getAdmin().enableTable(tableName); 357 LOG.debug("Waiting for no more RIT\n"); 358 blockUntilNoRIT(); 359 LOG.debug("Verifying there are " + numRegions + " assigned on cluster\n"); 360 regions = HBaseTestingUtil.getAllOnlineRegions(cluster); 361 assertEquals(numRegions + 1 + existingRegions, regions.size()); 362 return table; 363 } 364 365 void populateDataInTable(int nrows) throws Exception { 366 List<RegionServerThread> rsts = cluster.getLiveRegionServerThreads(); 367 assertEquals(NUM_RS, rsts.size()); 368 369 for (RegionServerThread rst : rsts) { 370 HRegionServer hrs = rst.getRegionServer(); 371 List<RegionInfo> hris = ProtobufUtil.getOnlineRegions(hrs.getRSRpcServices()); 372 for (RegionInfo hri : hris) { 373 if (hri.getTable().isSystemTable()) { 374 continue; 375 } 376 LOG.debug( 377 "adding data to rs = " + rst.getName() + " region = " + hri.getRegionNameAsString()); 378 Region region = hrs.getOnlineRegion(hri.getRegionName()); 379 assertTrue(region != null); 380 putData(region, hri.getStartKey(), nrows, Bytes.toBytes("q"), COLUMN_FAMILY); 381 } 382 } 383 } 384 385 public void makeWAL(HRegionServer hrs, List<RegionInfo> regions, int num_edits, int edit_size) 386 throws IOException { 387 makeWAL(hrs, regions, num_edits, edit_size, true); 388 } 389 390 public void makeWAL(HRegionServer hrs, List<RegionInfo> regions, int numEdits, int editSize, 391 boolean cleanShutdown) throws IOException { 392 // remove root and meta region 393 regions.remove(RegionInfoBuilder.FIRST_META_REGIONINFO); 394 395 for (Iterator<RegionInfo> iter = regions.iterator(); iter.hasNext();) { 396 RegionInfo regionInfo = iter.next(); 397 if (regionInfo.getTable().isSystemTable()) { 398 iter.remove(); 399 } 400 } 401 byte[] value = new byte[editSize]; 402 403 List<RegionInfo> hris = new ArrayList<>(); 404 for (RegionInfo region : regions) { 405 if (region.getTable() != tableName) { 406 continue; 407 } 408 hris.add(region); 409 } 410 LOG.info("Creating wal edits across " + hris.size() + " regions."); 411 for (int i = 0; i < editSize; i++) { 412 value[i] = (byte) ('a' + (i % 26)); 413 } 414 int n = hris.size(); 415 int[] counts = new int[n]; 416 // sync every ~30k to line up with desired wal rolls 417 final int syncEvery = 30 * 1024 / editSize; 418 MultiVersionConcurrencyControl mvcc = new MultiVersionConcurrencyControl(); 419 // HBASE-30335: match the per-region seqid invariant a real WAL preserves so the splitter's 420 // openSeqNum-seeded filter doesn't drop our injected edits as already-flushed. 421 long maxOpen = 0L; 422 for (RegionInfo info : hris) { 423 HRegion r = hrs.getRegion(info.getEncodedName()); 424 if (r != null) { 425 maxOpen = Math.max(maxOpen, r.getOpenSeqNum()); 426 } 427 } 428 if (maxOpen > 0L) { 429 mvcc.advanceTo(maxOpen); 430 } 431 if (n > 0) { 432 for (int i = 0; i < numEdits; i += 1) { 433 WALEdit e = new WALEdit(); 434 RegionInfo curRegionInfo = hris.get(i % n); 435 WAL log = hrs.getWAL(curRegionInfo); 436 byte[] startRow = curRegionInfo.getStartKey(); 437 if (startRow == null || startRow.length == 0) { 438 startRow = new byte[] { 0, 0, 0, 0, 1 }; 439 } 440 byte[] row = Bytes.incrementBytes(startRow, counts[i % n]); 441 row = Arrays.copyOfRange(row, 3, 8); // use last 5 bytes because 442 // HBaseTestingUtility.createMultiRegions use 5 bytes key 443 byte[] qualifier = Bytes.toBytes("c" + Integer.toString(i)); 444 WALEditInternalHelper.addExtendedCell(e, 445 new KeyValue(row, COLUMN_FAMILY, qualifier, EnvironmentEdgeManager.currentTime(), value)); 446 log.appendData(curRegionInfo, new WALKeyImpl(curRegionInfo.getEncodedNameAsBytes(), 447 tableName, EnvironmentEdgeManager.currentTime(), mvcc), e); 448 if (0 == i % syncEvery) { 449 log.sync(); 450 } 451 counts[i % n] += 1; 452 } 453 } 454 // done as two passes because the regions might share logs. shutdown is idempotent, but sync 455 // will cause errors if done after. 456 for (RegionInfo info : hris) { 457 WAL log = hrs.getWAL(info); 458 log.sync(); 459 } 460 if (cleanShutdown) { 461 for (RegionInfo info : hris) { 462 WAL log = hrs.getWAL(info); 463 log.shutdown(); 464 } 465 } 466 for (int i = 0; i < n; i++) { 467 LOG.info("region " + hris.get(i).getRegionNameAsString() + " has " + counts[i] + " edits"); 468 } 469 return; 470 } 471 472 private void blockUntilNoRIT() throws Exception { 473 TEST_UTIL.waitUntilNoRegionsInTransition(60000); 474 } 475 476 private void putData(Region region, byte[] startRow, int numRows, byte[] qf, byte[]... families) 477 throws IOException { 478 for (int i = 0; i < numRows; i++) { 479 Put put = new Put(Bytes.add(startRow, Bytes.toBytes(i))); 480 for (byte[] family : families) { 481 put.addColumn(family, qf, null); 482 } 483 region.put(put); 484 } 485 } 486 487 private void waitForCounter(LongAdder ctr, long oldval, long newval, long timems) 488 throws InterruptedException { 489 long curt = EnvironmentEdgeManager.currentTime(); 490 long endt = curt + timems; 491 while (curt < endt) { 492 if (ctr.sum() == oldval) { 493 Thread.sleep(100); 494 curt = EnvironmentEdgeManager.currentTime(); 495 } else { 496 assertEquals(newval, ctr.sum()); 497 return; 498 } 499 } 500 fail(); 501 } 502 503 private void abortMaster(SingleProcessHBaseCluster cluster) throws InterruptedException { 504 for (MasterThread mt : cluster.getLiveMasterThreads()) { 505 if (mt.getMaster().isActiveMaster()) { 506 mt.getMaster().abort("Aborting for tests", new Exception("Trace info")); 507 mt.join(); 508 break; 509 } 510 } 511 LOG.debug("Master is aborted"); 512 } 513 514 /** 515 * Find a RS that has regions of a table. 516 * @param hasMetaRegion when true, the returned RS has hbase:meta region as well 517 */ 518 private HRegionServer findRSToKill(boolean hasMetaRegion) throws Exception { 519 List<RegionServerThread> rsts = cluster.getLiveRegionServerThreads(); 520 List<RegionInfo> regions = null; 521 HRegionServer hrs = null; 522 523 for (RegionServerThread rst : rsts) { 524 hrs = rst.getRegionServer(); 525 while (rst.isAlive() && !hrs.isOnline()) { 526 Thread.sleep(100); 527 } 528 if (!rst.isAlive()) { 529 continue; 530 } 531 boolean isCarryingMeta = false; 532 boolean foundTableRegion = false; 533 regions = ProtobufUtil.getOnlineRegions(hrs.getRSRpcServices()); 534 for (RegionInfo region : regions) { 535 if (region.isMetaRegion()) { 536 isCarryingMeta = true; 537 } 538 if (region.getTable() == tableName) { 539 foundTableRegion = true; 540 } 541 if (foundTableRegion && (isCarryingMeta || !hasMetaRegion)) { 542 break; 543 } 544 } 545 if (isCarryingMeta && hasMetaRegion) { 546 // clients ask for a RS with META 547 if (!foundTableRegion) { 548 HRegionServer destRS = hrs; 549 // the RS doesn't have regions of the specified table so we need move one to this RS 550 List<RegionInfo> tableRegions = TEST_UTIL.getAdmin().getRegions(tableName); 551 RegionInfo hri = tableRegions.get(0); 552 TEST_UTIL.getAdmin().move(hri.getEncodedNameAsBytes(), destRS.getServerName()); 553 // wait for region move completes 554 RegionStates regionStates = 555 TEST_UTIL.getHBaseCluster().getMaster().getAssignmentManager().getRegionStates(); 556 TEST_UTIL.waitFor(45000, 200, new Waiter.Predicate<Exception>() { 557 @Override 558 public boolean evaluate() throws Exception { 559 ServerName sn = regionStates.getRegionServerOfRegion(hri); 560 return (sn != null && sn.equals(destRS.getServerName())); 561 } 562 }); 563 } 564 return hrs; 565 } else if (hasMetaRegion || isCarryingMeta) { 566 continue; 567 } 568 if (foundTableRegion) { 569 break; 570 } 571 } 572 573 return hrs; 574 } 575}