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.wal; 019 020import static org.junit.Assert.assertEquals; 021import static org.junit.Assert.assertFalse; 022import static org.junit.Assert.assertTrue; 023import static org.junit.Assert.fail; 024 025import java.io.FileNotFoundException; 026import java.io.IOException; 027import java.lang.reflect.Method; 028import java.security.PrivilegedExceptionAction; 029import java.util.ArrayList; 030import java.util.Arrays; 031import java.util.Collections; 032import java.util.HashMap; 033import java.util.HashSet; 034import java.util.List; 035import java.util.Map; 036import java.util.NavigableSet; 037import java.util.Objects; 038import java.util.Set; 039import java.util.concurrent.atomic.AtomicBoolean; 040import java.util.concurrent.atomic.AtomicInteger; 041import java.util.concurrent.atomic.AtomicLong; 042import java.util.stream.Collectors; 043import org.apache.hadoop.conf.Configuration; 044import org.apache.hadoop.fs.FSDataInputStream; 045import org.apache.hadoop.fs.FSDataOutputStream; 046import org.apache.hadoop.fs.FileStatus; 047import org.apache.hadoop.fs.FileSystem; 048import org.apache.hadoop.fs.FileUtil; 049import org.apache.hadoop.fs.Path; 050import org.apache.hadoop.fs.PathFilter; 051import org.apache.hadoop.hbase.Cell; 052import org.apache.hadoop.hbase.HBaseClassTestRule; 053import org.apache.hadoop.hbase.HBaseConfiguration; 054import org.apache.hadoop.hbase.HBaseTestingUtility; 055import org.apache.hadoop.hbase.HConstants; 056import org.apache.hadoop.hbase.KeyValue; 057import org.apache.hadoop.hbase.ServerName; 058import org.apache.hadoop.hbase.TableName; 059import org.apache.hadoop.hbase.client.RegionInfo; 060import org.apache.hadoop.hbase.client.RegionInfoBuilder; 061import org.apache.hadoop.hbase.regionserver.HRegion; 062import org.apache.hadoop.hbase.regionserver.wal.FaultyProtobufLogReader; 063import org.apache.hadoop.hbase.regionserver.wal.InstrumentedLogWriter; 064import org.apache.hadoop.hbase.regionserver.wal.ProtobufLogReader; 065import org.apache.hadoop.hbase.security.User; 066import org.apache.hadoop.hbase.testclassification.LargeTests; 067import org.apache.hadoop.hbase.testclassification.RegionServerTests; 068import org.apache.hadoop.hbase.util.Bytes; 069import org.apache.hadoop.hbase.util.CancelableProgressable; 070import org.apache.hadoop.hbase.util.EnvironmentEdgeManager; 071import org.apache.hadoop.hbase.util.FSUtils; 072import org.apache.hadoop.hbase.util.Threads; 073import org.apache.hadoop.hbase.wal.WAL.Entry; 074import org.apache.hadoop.hbase.wal.WAL.Reader; 075import org.apache.hadoop.hbase.wal.WALProvider.Writer; 076import org.apache.hadoop.hbase.wal.WALSplitter.CorruptedLogFileException; 077import org.apache.hadoop.hdfs.DFSTestUtil; 078import org.apache.hadoop.hdfs.server.namenode.LeaseExpiredException; 079import org.apache.hadoop.ipc.RemoteException; 080import org.junit.After; 081import org.junit.AfterClass; 082import org.junit.Before; 083import org.junit.BeforeClass; 084import org.junit.ClassRule; 085import org.junit.Rule; 086import org.junit.Test; 087import org.junit.experimental.categories.Category; 088import org.junit.rules.TestName; 089import org.mockito.Mockito; 090import org.mockito.invocation.InvocationOnMock; 091import org.mockito.stubbing.Answer; 092import org.slf4j.Logger; 093import org.slf4j.LoggerFactory; 094 095import org.apache.hbase.thirdparty.com.google.common.base.Joiner; 096import org.apache.hbase.thirdparty.com.google.common.collect.ImmutableList; 097import org.apache.hbase.thirdparty.com.google.common.collect.ImmutableMap; 098import org.apache.hbase.thirdparty.com.google.protobuf.ByteString; 099 100import org.apache.hadoop.hbase.shaded.protobuf.ProtobufUtil; 101import org.apache.hadoop.hbase.shaded.protobuf.generated.WALProtos; 102 103/** 104 * Testing {@link WAL} splitting code. 105 */ 106@Category({RegionServerTests.class, LargeTests.class}) 107public class TestWALSplit { 108 109 @ClassRule 110 public static final HBaseClassTestRule CLASS_RULE = 111 HBaseClassTestRule.forClass(TestWALSplit.class); 112 113 { 114 // Uncomment the following lines if more verbosity is needed for 115 // debugging (see HBASE-12285 for details). 116 //((Log4JLogger)DataNode.LOG).getLogger().setLevel(Level.ALL); 117 //((Log4JLogger)LeaseManager.LOG).getLogger().setLevel(Level.ALL); 118 //((Log4JLogger)FSNamesystem.LOG).getLogger().setLevel(Level.ALL); 119 } 120 private final static Logger LOG = LoggerFactory.getLogger(TestWALSplit.class); 121 122 private static Configuration conf; 123 private FileSystem fs; 124 125 protected final static HBaseTestingUtility TEST_UTIL = new HBaseTestingUtility(); 126 127 private Path HBASEDIR; 128 private Path HBASELOGDIR; 129 private Path WALDIR; 130 private Path OLDLOGDIR; 131 private Path CORRUPTDIR; 132 private Path TABLEDIR; 133 134 private static final int NUM_WRITERS = 10; 135 private static final int ENTRIES = 10; // entries per writer per region 136 137 private static final String FILENAME_BEING_SPLIT = "testfile"; 138 private static final TableName TABLE_NAME = 139 TableName.valueOf("t1"); 140 private static final byte[] FAMILY = Bytes.toBytes("f1"); 141 private static final byte[] QUALIFIER = Bytes.toBytes("q1"); 142 private static final byte[] VALUE = Bytes.toBytes("v1"); 143 private static final String WAL_FILE_PREFIX = "wal.dat."; 144 private static List<String> REGIONS = new ArrayList<>(); 145 private static final String HBASE_SKIP_ERRORS = "hbase.hlog.split.skip.errors"; 146 private static String ROBBER; 147 private static String ZOMBIE; 148 private static String [] GROUP = new String [] {"supergroup"}; 149 150 static enum Corruptions { 151 INSERT_GARBAGE_ON_FIRST_LINE, 152 INSERT_GARBAGE_IN_THE_MIDDLE, 153 APPEND_GARBAGE, 154 TRUNCATE, 155 TRUNCATE_TRAILER 156 } 157 158 @BeforeClass 159 public static void setUpBeforeClass() throws Exception { 160 conf = TEST_UTIL.getConfiguration(); 161 conf.setClass("hbase.regionserver.hlog.writer.impl", 162 InstrumentedLogWriter.class, Writer.class); 163 // This is how you turn off shortcircuit read currently. TODO: Fix. Should read config. 164 System.setProperty("hbase.tests.use.shortcircuit.reads", "false"); 165 // Create fake maping user to group and set it to the conf. 166 Map<String, String []> u2g_map = new HashMap<>(2); 167 ROBBER = User.getCurrent().getName() + "-robber"; 168 ZOMBIE = User.getCurrent().getName() + "-zombie"; 169 u2g_map.put(ROBBER, GROUP); 170 u2g_map.put(ZOMBIE, GROUP); 171 DFSTestUtil.updateConfWithFakeGroupMapping(conf, u2g_map); 172 conf.setInt("dfs.heartbeat.interval", 1); 173 TEST_UTIL.startMiniDFSCluster(2); 174 } 175 176 @AfterClass 177 public static void tearDownAfterClass() throws Exception { 178 TEST_UTIL.shutdownMiniDFSCluster(); 179 } 180 181 @Rule 182 public TestName name = new TestName(); 183 private WALFactory wals = null; 184 185 @Before 186 public void setUp() throws Exception { 187 LOG.info("Cleaning up cluster for new test."); 188 fs = TEST_UTIL.getDFSCluster().getFileSystem(); 189 HBASEDIR = TEST_UTIL.createRootDir(); 190 HBASELOGDIR = TEST_UTIL.createWALRootDir(); 191 OLDLOGDIR = new Path(HBASELOGDIR, HConstants.HREGION_OLDLOGDIR_NAME); 192 CORRUPTDIR = new Path(HBASELOGDIR, HConstants.CORRUPT_DIR_NAME); 193 TABLEDIR = FSUtils.getTableDir(HBASEDIR, TABLE_NAME); 194 REGIONS.clear(); 195 Collections.addAll(REGIONS, "bbb", "ccc"); 196 InstrumentedLogWriter.activateFailure = false; 197 wals = new WALFactory(conf, name.getMethodName()); 198 WALDIR = new Path(HBASELOGDIR, 199 AbstractFSWALProvider.getWALDirectoryName(ServerName.valueOf(name.getMethodName(), 200 16010, System.currentTimeMillis()).toString())); 201 //fs.mkdirs(WALDIR); 202 } 203 204 @After 205 public void tearDown() throws Exception { 206 try { 207 wals.close(); 208 } catch(IOException exception) { 209 // Some tests will move WALs out from under us. In those cases, we'll get an error on close. 210 LOG.info("Ignoring an error while closing down our WALFactory. Fine for some tests, but if" + 211 " you see a failure look here."); 212 LOG.debug("exception details", exception); 213 } finally { 214 wals = null; 215 fs.delete(HBASEDIR, true); 216 fs.delete(HBASELOGDIR, true); 217 } 218 } 219 220 /** 221 * Simulates splitting a WAL out from under a regionserver that is still trying to write it. 222 * Ensures we do not lose edits. 223 * @throws IOException 224 * @throws InterruptedException 225 */ 226 @Test 227 public void testLogCannotBeWrittenOnceParsed() throws IOException, InterruptedException { 228 final AtomicLong counter = new AtomicLong(0); 229 AtomicBoolean stop = new AtomicBoolean(false); 230 // Region we'll write edits too and then later examine to make sure they all made it in. 231 final String region = REGIONS.get(0); 232 final int numWriters = 3; 233 Thread zombie = new ZombieLastLogWriterRegionServer(counter, stop, region, numWriters); 234 try { 235 long startCount = counter.get(); 236 zombie.start(); 237 // Wait till writer starts going. 238 while (startCount == counter.get()) Threads.sleep(1); 239 // Give it a second to write a few appends. 240 Threads.sleep(1000); 241 final Configuration conf2 = HBaseConfiguration.create(conf); 242 final User robber = User.createUserForTesting(conf2, ROBBER, GROUP); 243 int count = robber.runAs(new PrivilegedExceptionAction<Integer>() { 244 @Override 245 public Integer run() throws Exception { 246 StringBuilder ls = new StringBuilder("Contents of WALDIR (").append(WALDIR) 247 .append("):\n"); 248 for (FileStatus status : fs.listStatus(WALDIR)) { 249 ls.append("\t").append(status.toString()).append("\n"); 250 } 251 LOG.debug(Objects.toString(ls)); 252 LOG.info("Splitting WALs out from under zombie. Expecting " + numWriters + " files."); 253 WALSplitter.split(HBASELOGDIR, WALDIR, OLDLOGDIR, fs, conf2, wals); 254 LOG.info("Finished splitting out from under zombie."); 255 Path[] logfiles = getLogForRegion(TABLE_NAME, region); 256 assertEquals("wrong number of split files for region", numWriters, logfiles.length); 257 int count = 0; 258 for (Path logfile: logfiles) { 259 count += countWAL(logfile); 260 } 261 return count; 262 } 263 }); 264 LOG.info("zombie=" + counter.get() + ", robber=" + count); 265 assertTrue("The log file could have at most 1 extra log entry, but can't have less. " + 266 "Zombie could write " + counter.get() + " and logfile had only " + count, 267 counter.get() == count || counter.get() + 1 == count); 268 } finally { 269 stop.set(true); 270 zombie.interrupt(); 271 Threads.threadDumpingIsAlive(zombie); 272 } 273 } 274 275 /** 276 * This thread will keep writing to a 'wal' file even after the split process has started. 277 * It simulates a region server that was considered dead but woke up and wrote some more to the 278 * last log entry. Does its writing as an alternate user in another filesystem instance to 279 * simulate better it being a regionserver. 280 */ 281 class ZombieLastLogWriterRegionServer extends Thread { 282 final AtomicLong editsCount; 283 final AtomicBoolean stop; 284 final int numOfWriters; 285 /** 286 * Region to write edits for. 287 */ 288 final String region; 289 final User user; 290 291 public ZombieLastLogWriterRegionServer(AtomicLong counter, AtomicBoolean stop, 292 final String region, final int writers) 293 throws IOException, InterruptedException { 294 super("ZombieLastLogWriterRegionServer"); 295 setDaemon(true); 296 this.stop = stop; 297 this.editsCount = counter; 298 this.region = region; 299 this.user = User.createUserForTesting(conf, ZOMBIE, GROUP); 300 numOfWriters = writers; 301 } 302 303 @Override 304 public void run() { 305 try { 306 doWriting(); 307 } catch (IOException e) { 308 LOG.warn(getName() + " Writer exiting " + e); 309 } catch (InterruptedException e) { 310 LOG.warn(getName() + " Writer exiting " + e); 311 } 312 } 313 314 private void doWriting() throws IOException, InterruptedException { 315 this.user.runAs(new PrivilegedExceptionAction<Object>() { 316 @Override 317 public Object run() throws Exception { 318 // Index of the WAL we want to keep open. generateWALs will leave open the WAL whose 319 // index we supply here. 320 int walToKeepOpen = numOfWriters - 1; 321 // The below method writes numOfWriters files each with ENTRIES entries for a total of 322 // numOfWriters * ENTRIES added per column family in the region. 323 Writer writer = null; 324 try { 325 writer = generateWALs(numOfWriters, ENTRIES, walToKeepOpen); 326 } catch (IOException e1) { 327 throw new RuntimeException("Failed", e1); 328 } 329 // Update counter so has all edits written so far. 330 editsCount.addAndGet(numOfWriters * ENTRIES); 331 loop(writer); 332 // If we've been interruped, then things should have shifted out from under us. 333 // closing should error 334 try { 335 writer.close(); 336 fail("Writing closing after parsing should give an error."); 337 } catch (IOException exception) { 338 LOG.debug("ignoring error when closing final writer.", exception); 339 } 340 return null; 341 } 342 }); 343 } 344 345 private void loop(final Writer writer) { 346 byte [] regionBytes = Bytes.toBytes(this.region); 347 while (!stop.get()) { 348 try { 349 long seq = appendEntry(writer, TABLE_NAME, regionBytes, 350 Bytes.toBytes("r" + editsCount.get()), regionBytes, QUALIFIER, VALUE, 0); 351 long count = editsCount.incrementAndGet(); 352 LOG.info(getName() + " sync count=" + count + ", seq=" + seq); 353 try { 354 Thread.sleep(1); 355 } catch (InterruptedException e) { 356 // 357 } 358 } catch (IOException ex) { 359 LOG.error(getName() + " ex " + ex.toString()); 360 if (ex instanceof RemoteException) { 361 LOG.error("Juliet: got RemoteException " + ex.getMessage() + 362 " while writing " + (editsCount.get() + 1)); 363 } else { 364 LOG.error(getName() + " failed to write....at " + editsCount.get()); 365 fail("Failed to write " + editsCount.get()); 366 } 367 break; 368 } catch (Throwable t) { 369 LOG.error(getName() + " HOW? " + t); 370 LOG.debug("exception details", t); 371 break; 372 } 373 } 374 LOG.info(getName() + " Writer exiting"); 375 } 376 } 377 378 /** 379 * {@see https://issues.apache.org/jira/browse/HBASE-3020} 380 */ 381 @Test 382 public void testRecoveredEditsPathForMeta() throws IOException { 383 byte[] encoded = RegionInfoBuilder.FIRST_META_REGIONINFO.getEncodedNameAsBytes(); 384 Path tdir = FSUtils.getTableDir(HBASEDIR, TableName.META_TABLE_NAME); 385 Path regiondir = new Path(tdir, 386 RegionInfoBuilder.FIRST_META_REGIONINFO.getEncodedName()); 387 fs.mkdirs(regiondir); 388 long now = System.currentTimeMillis(); 389 Entry entry = 390 new Entry(new WALKeyImpl(encoded, 391 TableName.META_TABLE_NAME, 1, now, HConstants.DEFAULT_CLUSTER_ID), 392 new WALEdit()); 393 Path p = WALSplitter.getRegionSplitEditsPath(entry, 394 FILENAME_BEING_SPLIT, conf); 395 String parentOfParent = p.getParent().getParent().getName(); 396 assertEquals(parentOfParent, RegionInfoBuilder.FIRST_META_REGIONINFO.getEncodedName()); 397 } 398 399 /** 400 * Test old recovered edits file doesn't break WALSplitter. 401 * This is useful in upgrading old instances. 402 */ 403 @Test 404 public void testOldRecoveredEditsFileSidelined() throws IOException { 405 byte [] encoded = RegionInfoBuilder.FIRST_META_REGIONINFO.getEncodedNameAsBytes(); 406 Path tdir = FSUtils.getTableDir(HBASEDIR, TableName.META_TABLE_NAME); 407 Path regiondir = new Path(tdir, 408 RegionInfoBuilder.FIRST_META_REGIONINFO.getEncodedName()); 409 fs.mkdirs(regiondir); 410 long now = System.currentTimeMillis(); 411 Entry entry = 412 new Entry(new WALKeyImpl(encoded, 413 TableName.META_TABLE_NAME, 1, now, HConstants.DEFAULT_CLUSTER_ID), 414 new WALEdit()); 415 Path parent = WALSplitter.getRegionDirRecoveredEditsDir(regiondir); 416 assertEquals(HConstants.RECOVERED_EDITS_DIR, parent.getName()); 417 fs.createNewFile(parent); // create a recovered.edits file 418 419 Path p = WALSplitter.getRegionSplitEditsPath(entry, 420 FILENAME_BEING_SPLIT, conf); 421 String parentOfParent = p.getParent().getParent().getName(); 422 assertEquals(parentOfParent, RegionInfoBuilder.FIRST_META_REGIONINFO.getEncodedName()); 423 WALFactory.createRecoveredEditsWriter(fs, p, conf).close(); 424 } 425 426 private void useDifferentDFSClient() throws IOException { 427 // make fs act as a different client now 428 // initialize will create a new DFSClient with a new client ID 429 fs.initialize(fs.getUri(), conf); 430 } 431 432 @Test 433 public void testSplitPreservesEdits() throws IOException{ 434 final String REGION = "region__1"; 435 REGIONS.clear(); 436 REGIONS.add(REGION); 437 438 generateWALs(1, 10, -1, 0); 439 useDifferentDFSClient(); 440 WALSplitter.split(HBASELOGDIR, WALDIR, OLDLOGDIR, fs, conf, wals); 441 Path originalLog = (fs.listStatus(OLDLOGDIR))[0].getPath(); 442 Path[] splitLog = getLogForRegion(TABLE_NAME, REGION); 443 assertEquals(1, splitLog.length); 444 445 assertTrue("edits differ after split", logsAreEqual(originalLog, splitLog[0])); 446 } 447 448 @Test 449 public void testSplitRemovesRegionEventsEdits() throws IOException{ 450 final String REGION = "region__1"; 451 REGIONS.clear(); 452 REGIONS.add(REGION); 453 454 generateWALs(1, 10, -1, 100); 455 useDifferentDFSClient(); 456 WALSplitter.split(HBASELOGDIR, WALDIR, OLDLOGDIR, fs, conf, wals); 457 Path originalLog = (fs.listStatus(OLDLOGDIR))[0].getPath(); 458 Path[] splitLog = getLogForRegion(TABLE_NAME, REGION); 459 assertEquals(1, splitLog.length); 460 461 assertFalse("edits differ after split", logsAreEqual(originalLog, splitLog[0])); 462 // split log should only have the test edits 463 assertEquals(10, countWAL(splitLog[0])); 464 } 465 466 467 @Test 468 public void testSplitLeavesCompactionEventsEdits() throws IOException{ 469 RegionInfo hri = RegionInfoBuilder.newBuilder(TABLE_NAME).build(); 470 REGIONS.clear(); 471 REGIONS.add(hri.getEncodedName()); 472 Path regionDir = new Path(FSUtils.getTableDir(HBASEDIR, TABLE_NAME), hri.getEncodedName()); 473 LOG.info("Creating region directory: " + regionDir); 474 assertTrue(fs.mkdirs(regionDir)); 475 476 Writer writer = generateWALs(1, 10, 0, 10); 477 String[] compactInputs = new String[]{"file1", "file2", "file3"}; 478 String compactOutput = "file4"; 479 appendCompactionEvent(writer, hri, compactInputs, compactOutput); 480 writer.close(); 481 482 useDifferentDFSClient(); 483 WALSplitter.split(HBASELOGDIR, WALDIR, OLDLOGDIR, fs, conf, wals); 484 485 Path originalLog = (fs.listStatus(OLDLOGDIR))[0].getPath(); 486 // original log should have 10 test edits, 10 region markers, 1 compaction marker 487 assertEquals(21, countWAL(originalLog)); 488 489 Path[] splitLog = getLogForRegion(TABLE_NAME, hri.getEncodedName()); 490 assertEquals(1, splitLog.length); 491 492 assertFalse("edits differ after split", logsAreEqual(originalLog, splitLog[0])); 493 // split log should have 10 test edits plus 1 compaction marker 494 assertEquals(11, countWAL(splitLog[0])); 495 } 496 497 /** 498 * @param expectedEntries -1 to not assert 499 * @return the count across all regions 500 */ 501 private int splitAndCount(final int expectedFiles, final int expectedEntries) 502 throws IOException { 503 useDifferentDFSClient(); 504 WALSplitter.split(HBASELOGDIR, WALDIR, OLDLOGDIR, fs, conf, wals); 505 int result = 0; 506 for (String region : REGIONS) { 507 Path[] logfiles = getLogForRegion(TABLE_NAME, region); 508 assertEquals(expectedFiles, logfiles.length); 509 int count = 0; 510 for (Path logfile: logfiles) { 511 count += countWAL(logfile); 512 } 513 if (-1 != expectedEntries) { 514 assertEquals(expectedEntries, count); 515 } 516 result += count; 517 } 518 return result; 519 } 520 521 @Test 522 public void testEmptyLogFiles() throws IOException { 523 testEmptyLogFiles(true); 524 } 525 526 @Test 527 public void testEmptyOpenLogFiles() throws IOException { 528 testEmptyLogFiles(false); 529 } 530 531 private void testEmptyLogFiles(final boolean close) throws IOException { 532 // we won't create the hlog dir until getWAL got called, so 533 // make dir here when testing empty log file 534 fs.mkdirs(WALDIR); 535 injectEmptyFile(".empty", close); 536 generateWALs(Integer.MAX_VALUE); 537 injectEmptyFile("empty", close); 538 splitAndCount(NUM_WRITERS, NUM_WRITERS * ENTRIES); // skip 2 empty 539 } 540 541 @Test 542 public void testOpenZeroLengthReportedFileButWithDataGetsSplit() throws IOException { 543 // generate logs but leave wal.dat.5 open. 544 generateWALs(5); 545 splitAndCount(NUM_WRITERS, NUM_WRITERS * ENTRIES); 546 } 547 548 @Test 549 public void testTralingGarbageCorruptionFileSkipErrorsPasses() throws IOException { 550 conf.setBoolean(HBASE_SKIP_ERRORS, true); 551 generateWALs(Integer.MAX_VALUE); 552 corruptWAL(new Path(WALDIR, WAL_FILE_PREFIX + "5"), 553 Corruptions.APPEND_GARBAGE, true); 554 splitAndCount(NUM_WRITERS, NUM_WRITERS * ENTRIES); 555 } 556 557 @Test 558 public void testFirstLineCorruptionLogFileSkipErrorsPasses() throws IOException { 559 conf.setBoolean(HBASE_SKIP_ERRORS, true); 560 generateWALs(Integer.MAX_VALUE); 561 corruptWAL(new Path(WALDIR, WAL_FILE_PREFIX + "5"), 562 Corruptions.INSERT_GARBAGE_ON_FIRST_LINE, true); 563 splitAndCount(NUM_WRITERS - 1, (NUM_WRITERS - 1) * ENTRIES); //1 corrupt 564 } 565 566 @Test 567 public void testMiddleGarbageCorruptionSkipErrorsReadsHalfOfFile() throws IOException { 568 conf.setBoolean(HBASE_SKIP_ERRORS, true); 569 generateWALs(Integer.MAX_VALUE); 570 corruptWAL(new Path(WALDIR, WAL_FILE_PREFIX + "5"), 571 Corruptions.INSERT_GARBAGE_IN_THE_MIDDLE, false); 572 // the entries in the original logs are alternating regions 573 // considering the sequence file header, the middle corruption should 574 // affect at least half of the entries 575 int goodEntries = (NUM_WRITERS - 1) * ENTRIES; 576 int firstHalfEntries = (int) Math.ceil(ENTRIES / 2) - 1; 577 int allRegionsCount = splitAndCount(NUM_WRITERS, -1); 578 assertTrue("The file up to the corrupted area hasn't been parsed", 579 REGIONS.size() * (goodEntries + firstHalfEntries) <= allRegionsCount); 580 } 581 582 @Test 583 public void testCorruptedFileGetsArchivedIfSkipErrors() throws IOException { 584 conf.setBoolean(HBASE_SKIP_ERRORS, true); 585 List<FaultyProtobufLogReader.FailureType> failureTypes = Arrays 586 .asList(FaultyProtobufLogReader.FailureType.values()).stream() 587 .filter(x -> x != FaultyProtobufLogReader.FailureType.NONE).collect(Collectors.toList()); 588 for (FaultyProtobufLogReader.FailureType failureType : failureTypes) { 589 final Set<String> walDirContents = splitCorruptWALs(failureType); 590 final Set<String> archivedLogs = new HashSet<>(); 591 final StringBuilder archived = new StringBuilder("Archived logs in CORRUPTDIR:"); 592 for (FileStatus log : fs.listStatus(CORRUPTDIR)) { 593 archived.append("\n\t").append(log.toString()); 594 archivedLogs.add(log.getPath().getName()); 595 } 596 LOG.debug(archived.toString()); 597 assertEquals(failureType.name() + ": expected to find all of our wals corrupt.", archivedLogs, 598 walDirContents); 599 } 600 } 601 602 /** 603 * @return set of wal names present prior to split attempt. 604 * @throws IOException if the split process fails 605 */ 606 private Set<String> splitCorruptWALs(final FaultyProtobufLogReader.FailureType failureType) 607 throws IOException { 608 Class<?> backupClass = conf.getClass("hbase.regionserver.hlog.reader.impl", 609 Reader.class); 610 InstrumentedLogWriter.activateFailure = false; 611 612 try { 613 conf.setClass("hbase.regionserver.hlog.reader.impl", FaultyProtobufLogReader.class, 614 Reader.class); 615 conf.set("faultyprotobuflogreader.failuretype", failureType.name()); 616 // Clean up from previous tests or previous loop 617 try { 618 wals.shutdown(); 619 } catch (IOException exception) { 620 // since we're splitting out from under the factory, we should expect some closing failures. 621 LOG.debug("Ignoring problem closing WALFactory.", exception); 622 } 623 wals.close(); 624 try { 625 for (FileStatus log : fs.listStatus(CORRUPTDIR)) { 626 fs.delete(log.getPath(), true); 627 } 628 } catch (FileNotFoundException exception) { 629 LOG.debug("no previous CORRUPTDIR to clean."); 630 } 631 // change to the faulty reader 632 wals = new WALFactory(conf, name.getMethodName()); 633 generateWALs(-1); 634 // Our reader will render all of these files corrupt. 635 final Set<String> walDirContents = new HashSet<>(); 636 for (FileStatus status : fs.listStatus(WALDIR)) { 637 walDirContents.add(status.getPath().getName()); 638 } 639 useDifferentDFSClient(); 640 WALSplitter.split(HBASELOGDIR, WALDIR, OLDLOGDIR, fs, conf, wals); 641 return walDirContents; 642 } finally { 643 conf.setClass("hbase.regionserver.hlog.reader.impl", backupClass, 644 Reader.class); 645 } 646 } 647 648 @Test (expected = IOException.class) 649 public void testTrailingGarbageCorruptionLogFileSkipErrorsFalseThrows() 650 throws IOException { 651 conf.setBoolean(HBASE_SKIP_ERRORS, false); 652 splitCorruptWALs(FaultyProtobufLogReader.FailureType.BEGINNING); 653 } 654 655 @Test 656 public void testCorruptedLogFilesSkipErrorsFalseDoesNotTouchLogs() 657 throws IOException { 658 conf.setBoolean(HBASE_SKIP_ERRORS, false); 659 try { 660 splitCorruptWALs(FaultyProtobufLogReader.FailureType.BEGINNING); 661 } catch (IOException e) { 662 LOG.debug("split with 'skip errors' set to 'false' correctly threw"); 663 } 664 assertEquals("if skip.errors is false all files should remain in place", 665 NUM_WRITERS, fs.listStatus(WALDIR).length); 666 } 667 668 private void ignoreCorruption(final Corruptions corruption, final int entryCount, 669 final int expectedCount) throws IOException { 670 conf.setBoolean(HBASE_SKIP_ERRORS, false); 671 672 final String REGION = "region__1"; 673 REGIONS.clear(); 674 REGIONS.add(REGION); 675 676 Path c1 = new Path(WALDIR, WAL_FILE_PREFIX + "0"); 677 generateWALs(1, entryCount, -1, 0); 678 corruptWAL(c1, corruption, true); 679 680 useDifferentDFSClient(); 681 WALSplitter.split(HBASELOGDIR, WALDIR, OLDLOGDIR, fs, conf, wals); 682 683 Path[] splitLog = getLogForRegion(TABLE_NAME, REGION); 684 assertEquals(1, splitLog.length); 685 686 int actualCount = 0; 687 Reader in = wals.createReader(fs, splitLog[0]); 688 @SuppressWarnings("unused") 689 Entry entry; 690 while ((entry = in.next()) != null) ++actualCount; 691 assertEquals(expectedCount, actualCount); 692 in.close(); 693 694 // should not have stored the EOF files as corrupt 695 FileStatus[] archivedLogs = fs.listStatus(CORRUPTDIR); 696 assertEquals(0, archivedLogs.length); 697 698 } 699 700 @Test 701 public void testEOFisIgnored() throws IOException { 702 int entryCount = 10; 703 ignoreCorruption(Corruptions.TRUNCATE, entryCount, entryCount-1); 704 } 705 706 @Test 707 public void testCorruptWALTrailer() throws IOException { 708 int entryCount = 10; 709 ignoreCorruption(Corruptions.TRUNCATE_TRAILER, entryCount, entryCount); 710 } 711 712 @Test 713 public void testLogsGetArchivedAfterSplit() throws IOException { 714 conf.setBoolean(HBASE_SKIP_ERRORS, false); 715 generateWALs(-1); 716 useDifferentDFSClient(); 717 WALSplitter.split(HBASELOGDIR, WALDIR, OLDLOGDIR, fs, conf, wals); 718 FileStatus[] archivedLogs = fs.listStatus(OLDLOGDIR); 719 assertEquals("wrong number of files in the archive log", NUM_WRITERS, archivedLogs.length); 720 } 721 722 @Test 723 public void testSplit() throws IOException { 724 generateWALs(-1); 725 splitAndCount(NUM_WRITERS, NUM_WRITERS * ENTRIES); 726 } 727 728 @Test 729 public void testLogDirectoryShouldBeDeletedAfterSuccessfulSplit() 730 throws IOException { 731 generateWALs(-1); 732 useDifferentDFSClient(); 733 WALSplitter.split(HBASELOGDIR, WALDIR, OLDLOGDIR, fs, conf, wals); 734 FileStatus [] statuses = null; 735 try { 736 statuses = fs.listStatus(WALDIR); 737 if (statuses != null) { 738 fail("Files left in log dir: " + 739 Joiner.on(",").join(FileUtil.stat2Paths(statuses))); 740 } 741 } catch (FileNotFoundException e) { 742 // hadoop 0.21 throws FNFE whereas hadoop 0.20 returns null 743 } 744 } 745 746 @Test(expected = IOException.class) 747 public void testSplitWillFailIfWritingToRegionFails() throws Exception { 748 //leave 5th log open so we could append the "trap" 749 Writer writer = generateWALs(4); 750 useDifferentDFSClient(); 751 752 String region = "break"; 753 Path regiondir = new Path(TABLEDIR, region); 754 fs.mkdirs(regiondir); 755 756 InstrumentedLogWriter.activateFailure = false; 757 appendEntry(writer, TABLE_NAME, Bytes.toBytes(region), 758 Bytes.toBytes("r" + 999), FAMILY, QUALIFIER, VALUE, 0); 759 writer.close(); 760 761 try { 762 InstrumentedLogWriter.activateFailure = true; 763 WALSplitter.split(HBASELOGDIR, WALDIR, OLDLOGDIR, fs, conf, wals); 764 } catch (IOException e) { 765 assertTrue(e.getMessage(). 766 contains("This exception is instrumented and should only be thrown for testing")); 767 throw e; 768 } finally { 769 InstrumentedLogWriter.activateFailure = false; 770 } 771 } 772 773 @Test 774 public void testSplitDeletedRegion() throws IOException { 775 REGIONS.clear(); 776 String region = "region_that_splits"; 777 REGIONS.add(region); 778 779 generateWALs(1); 780 useDifferentDFSClient(); 781 782 Path regiondir = new Path(TABLEDIR, region); 783 fs.delete(regiondir, true); 784 WALSplitter.split(HBASELOGDIR, WALDIR, OLDLOGDIR, fs, conf, wals); 785 assertFalse(fs.exists(regiondir)); 786 } 787 788 @Test 789 public void testIOEOnOutputThread() throws Exception { 790 conf.setBoolean(HBASE_SKIP_ERRORS, false); 791 792 generateWALs(-1); 793 useDifferentDFSClient(); 794 FileStatus[] logfiles = fs.listStatus(WALDIR); 795 assertTrue("There should be some log file", 796 logfiles != null && logfiles.length > 0); 797 // wals with no entries (like the one we don't use in the factory) 798 // won't cause a failure since nothing will ever be written. 799 // pick the largest one since it's most likely to have entries. 800 int largestLogFile = 0; 801 long largestSize = 0; 802 for (int i = 0; i < logfiles.length; i++) { 803 if (logfiles[i].getLen() > largestSize) { 804 largestLogFile = i; 805 largestSize = logfiles[i].getLen(); 806 } 807 } 808 assertTrue("There should be some log greater than size 0.", 0 < largestSize); 809 // Set up a splitter that will throw an IOE on the output side 810 WALSplitter logSplitter = new WALSplitter(wals, conf, HBASEDIR, fs, null, null) { 811 @Override 812 protected Writer createWriter(Path logfile) throws IOException { 813 Writer mockWriter = Mockito.mock(Writer.class); 814 Mockito.doThrow(new IOException("Injected")).when( 815 mockWriter).append(Mockito.<Entry>any()); 816 return mockWriter; 817 } 818 }; 819 // Set up a background thread dumper. Needs a thread to depend on and then we need to run 820 // the thread dumping in a background thread so it does not hold up the test. 821 final AtomicBoolean stop = new AtomicBoolean(false); 822 final Thread someOldThread = new Thread("Some-old-thread") { 823 @Override 824 public void run() { 825 while(!stop.get()) Threads.sleep(10); 826 } 827 }; 828 someOldThread.setDaemon(true); 829 someOldThread.start(); 830 final Thread t = new Thread("Background-thread-dumper") { 831 @Override 832 public void run() { 833 try { 834 Threads.threadDumpingIsAlive(someOldThread); 835 } catch (InterruptedException e) { 836 e.printStackTrace(); 837 } 838 } 839 }; 840 t.setDaemon(true); 841 t.start(); 842 try { 843 logSplitter.splitLogFile(logfiles[largestLogFile], null); 844 fail("Didn't throw!"); 845 } catch (IOException ioe) { 846 assertTrue(ioe.toString().contains("Injected")); 847 } finally { 848 // Setting this to true will turn off the background thread dumper. 849 stop.set(true); 850 } 851 } 852 853 /** 854 * @param spiedFs should be instrumented for failure. 855 */ 856 private void retryOverHdfsProblem(final FileSystem spiedFs) throws Exception { 857 generateWALs(-1); 858 useDifferentDFSClient(); 859 860 try { 861 WALSplitter.split(HBASELOGDIR, WALDIR, OLDLOGDIR, spiedFs, conf, wals); 862 assertEquals(NUM_WRITERS, fs.listStatus(OLDLOGDIR).length); 863 assertFalse(fs.exists(WALDIR)); 864 } catch (IOException e) { 865 fail("There shouldn't be any exception but: " + e.toString()); 866 } 867 } 868 869 // Test for HBASE-3412 870 @Test 871 public void testMovedWALDuringRecovery() throws Exception { 872 // This partial mock will throw LEE for every file simulating 873 // files that were moved 874 FileSystem spiedFs = Mockito.spy(fs); 875 // The "File does not exist" part is very important, 876 // that's how it comes out of HDFS 877 Mockito.doThrow(new LeaseExpiredException("Injected: File does not exist")). 878 when(spiedFs).append(Mockito.<Path>any()); 879 retryOverHdfsProblem(spiedFs); 880 } 881 882 @Test 883 public void testRetryOpenDuringRecovery() throws Exception { 884 FileSystem spiedFs = Mockito.spy(fs); 885 // The "Cannot obtain block length", "Could not obtain the last block", 886 // and "Blocklist for [^ ]* has changed.*" part is very important, 887 // that's how it comes out of HDFS. If HDFS changes the exception 888 // message, this test needs to be adjusted accordingly. 889 // 890 // When DFSClient tries to open a file, HDFS needs to locate 891 // the last block of the file and get its length. However, if the 892 // last block is under recovery, HDFS may have problem to obtain 893 // the block length, in which case, retry may help. 894 Mockito.doAnswer(new Answer<FSDataInputStream>() { 895 private final String[] errors = new String[] { 896 "Cannot obtain block length", "Could not obtain the last block", 897 "Blocklist for " + OLDLOGDIR + " has changed"}; 898 private int count = 0; 899 900 @Override 901 public FSDataInputStream answer(InvocationOnMock invocation) throws Throwable { 902 if (count < 3) { 903 throw new IOException(errors[count++]); 904 } 905 return (FSDataInputStream)invocation.callRealMethod(); 906 } 907 }).when(spiedFs).open(Mockito.<Path>any(), Mockito.anyInt()); 908 retryOverHdfsProblem(spiedFs); 909 } 910 911 @Test 912 public void testTerminationAskedByReporter() throws IOException, CorruptedLogFileException { 913 generateWALs(1, 10, -1); 914 FileStatus logfile = fs.listStatus(WALDIR)[0]; 915 useDifferentDFSClient(); 916 917 final AtomicInteger count = new AtomicInteger(); 918 919 CancelableProgressable localReporter 920 = new CancelableProgressable() { 921 @Override 922 public boolean progress() { 923 count.getAndIncrement(); 924 return false; 925 } 926 }; 927 928 FileSystem spiedFs = Mockito.spy(fs); 929 Mockito.doAnswer(new Answer<FSDataInputStream>() { 930 @Override 931 public FSDataInputStream answer(InvocationOnMock invocation) throws Throwable { 932 Thread.sleep(1500); // Sleep a while and wait report status invoked 933 return (FSDataInputStream)invocation.callRealMethod(); 934 } 935 }).when(spiedFs).open(Mockito.<Path>any(), Mockito.anyInt()); 936 937 try { 938 conf.setInt("hbase.splitlog.report.period", 1000); 939 boolean ret = WALSplitter.splitLogFile( 940 HBASEDIR, logfile, spiedFs, conf, localReporter, null, null, wals); 941 assertFalse("Log splitting should failed", ret); 942 assertTrue(count.get() > 0); 943 } catch (IOException e) { 944 fail("There shouldn't be any exception but: " + e.toString()); 945 } finally { 946 // reset it back to its default value 947 conf.setInt("hbase.splitlog.report.period", 59000); 948 } 949 } 950 951 /** 952 * Test log split process with fake data and lots of edits to trigger threading 953 * issues. 954 */ 955 @Test 956 public void testThreading() throws Exception { 957 doTestThreading(20000, 128*1024*1024, 0); 958 } 959 960 /** 961 * Test blocking behavior of the log split process if writers are writing slower 962 * than the reader is reading. 963 */ 964 @Test 965 public void testThreadingSlowWriterSmallBuffer() throws Exception { 966 doTestThreading(200, 1024, 50); 967 } 968 969 /** 970 * Sets up a log splitter with a mock reader and writer. The mock reader generates 971 * a specified number of edits spread across 5 regions. The mock writer optionally 972 * sleeps for each edit it is fed. 973 * * 974 * After the split is complete, verifies that the statistics show the correct number 975 * of edits output into each region. 976 * 977 * @param numFakeEdits number of fake edits to push through pipeline 978 * @param bufferSize size of in-memory buffer 979 * @param writerSlowness writer threads will sleep this many ms per edit 980 */ 981 private void doTestThreading(final int numFakeEdits, 982 final int bufferSize, 983 final int writerSlowness) throws Exception { 984 985 Configuration localConf = new Configuration(conf); 986 localConf.setInt("hbase.regionserver.hlog.splitlog.buffersize", bufferSize); 987 988 // Create a fake log file (we'll override the reader to produce a stream of edits) 989 Path logPath = new Path(WALDIR, WAL_FILE_PREFIX + ".fake"); 990 FSDataOutputStream out = fs.create(logPath); 991 out.close(); 992 993 // Make region dirs for our destination regions so the output doesn't get skipped 994 final List<String> regions = ImmutableList.of("r0", "r1", "r2", "r3", "r4"); 995 makeRegionDirs(regions); 996 997 // Create a splitter that reads and writes the data without touching disk 998 WALSplitter logSplitter = new WALSplitter(wals, localConf, HBASEDIR, fs, null, null) { 999 1000 /* Produce a mock writer that doesn't write anywhere */ 1001 @Override 1002 protected Writer createWriter(Path logfile) throws IOException { 1003 Writer mockWriter = Mockito.mock(Writer.class); 1004 Mockito.doAnswer(new Answer<Void>() { 1005 int expectedIndex = 0; 1006 1007 @Override 1008 public Void answer(InvocationOnMock invocation) { 1009 if (writerSlowness > 0) { 1010 try { 1011 Thread.sleep(writerSlowness); 1012 } catch (InterruptedException ie) { 1013 Thread.currentThread().interrupt(); 1014 } 1015 } 1016 Entry entry = (Entry) invocation.getArgument(0); 1017 WALEdit edit = entry.getEdit(); 1018 List<Cell> cells = edit.getCells(); 1019 assertEquals(1, cells.size()); 1020 Cell cell = cells.get(0); 1021 1022 // Check that the edits come in the right order. 1023 assertEquals(expectedIndex, Bytes.toInt(cell.getRowArray(), cell.getRowOffset(), 1024 cell.getRowLength())); 1025 expectedIndex++; 1026 return null; 1027 } 1028 }).when(mockWriter).append(Mockito.<Entry>any()); 1029 return mockWriter; 1030 } 1031 1032 /* Produce a mock reader that generates fake entries */ 1033 @Override 1034 protected Reader getReader(Path curLogFile, CancelableProgressable reporter) 1035 throws IOException { 1036 Reader mockReader = Mockito.mock(Reader.class); 1037 Mockito.doAnswer(new Answer<Entry>() { 1038 int index = 0; 1039 1040 @Override 1041 public Entry answer(InvocationOnMock invocation) throws Throwable { 1042 if (index >= numFakeEdits) return null; 1043 1044 // Generate r0 through r4 in round robin fashion 1045 int regionIdx = index % regions.size(); 1046 byte region[] = new byte[] {(byte)'r', (byte) (0x30 + regionIdx)}; 1047 1048 Entry ret = createTestEntry(TABLE_NAME, region, 1049 Bytes.toBytes(index / regions.size()), 1050 FAMILY, QUALIFIER, VALUE, index); 1051 index++; 1052 return ret; 1053 } 1054 }).when(mockReader).next(); 1055 return mockReader; 1056 } 1057 }; 1058 1059 logSplitter.splitLogFile(fs.getFileStatus(logPath), null); 1060 1061 // Verify number of written edits per region 1062 Map<byte[], Long> outputCounts = logSplitter.outputSink.getOutputCounts(); 1063 for (Map.Entry<byte[], Long> entry : outputCounts.entrySet()) { 1064 LOG.info("Got " + entry.getValue() + " output edits for region " + 1065 Bytes.toString(entry.getKey())); 1066 assertEquals((long)entry.getValue(), numFakeEdits / regions.size()); 1067 } 1068 assertEquals("Should have as many outputs as regions", regions.size(), outputCounts.size()); 1069 } 1070 1071 // Does leaving the writer open in testSplitDeletedRegion matter enough for two tests? 1072 @Test 1073 public void testSplitLogFileDeletedRegionDir() throws IOException { 1074 LOG.info("testSplitLogFileDeletedRegionDir"); 1075 final String REGION = "region__1"; 1076 REGIONS.clear(); 1077 REGIONS.add(REGION); 1078 1079 generateWALs(1, 10, -1); 1080 useDifferentDFSClient(); 1081 1082 Path regiondir = new Path(TABLEDIR, REGION); 1083 LOG.info("Region directory is" + regiondir); 1084 fs.delete(regiondir, true); 1085 WALSplitter.split(HBASELOGDIR, WALDIR, OLDLOGDIR, fs, conf, wals); 1086 assertFalse(fs.exists(regiondir)); 1087 } 1088 1089 @Test 1090 public void testSplitLogFileEmpty() throws IOException { 1091 LOG.info("testSplitLogFileEmpty"); 1092 // we won't create the hlog dir until getWAL got called, so 1093 // make dir here when testing empty log file 1094 fs.mkdirs(WALDIR); 1095 injectEmptyFile(".empty", true); 1096 useDifferentDFSClient(); 1097 1098 WALSplitter.split(HBASELOGDIR, WALDIR, OLDLOGDIR, fs, conf, wals); 1099 Path tdir = FSUtils.getTableDir(HBASEDIR, TABLE_NAME); 1100 assertFalse(fs.exists(tdir)); 1101 1102 assertEquals(0, countWAL(fs.listStatus(OLDLOGDIR)[0].getPath())); 1103 } 1104 1105 @Test 1106 public void testSplitLogFileMultipleRegions() throws IOException { 1107 LOG.info("testSplitLogFileMultipleRegions"); 1108 generateWALs(1, 10, -1); 1109 splitAndCount(1, 10); 1110 } 1111 1112 @Test 1113 public void testSplitLogFileFirstLineCorruptionLog() 1114 throws IOException { 1115 conf.setBoolean(HBASE_SKIP_ERRORS, true); 1116 generateWALs(1, 10, -1); 1117 FileStatus logfile = fs.listStatus(WALDIR)[0]; 1118 1119 corruptWAL(logfile.getPath(), 1120 Corruptions.INSERT_GARBAGE_ON_FIRST_LINE, true); 1121 1122 useDifferentDFSClient(); 1123 WALSplitter.split(HBASELOGDIR, WALDIR, OLDLOGDIR, fs, conf, wals); 1124 1125 final Path corruptDir = new Path(FSUtils.getWALRootDir(conf), HConstants.CORRUPT_DIR_NAME); 1126 assertEquals(1, fs.listStatus(corruptDir).length); 1127 } 1128 1129 /** 1130 * {@see https://issues.apache.org/jira/browse/HBASE-4862} 1131 */ 1132 @Test 1133 public void testConcurrentSplitLogAndReplayRecoverEdit() throws IOException { 1134 LOG.info("testConcurrentSplitLogAndReplayRecoverEdit"); 1135 // Generate wals for our destination region 1136 String regionName = "r0"; 1137 final Path regiondir = new Path(TABLEDIR, regionName); 1138 REGIONS.clear(); 1139 REGIONS.add(regionName); 1140 generateWALs(-1); 1141 1142 wals.getWAL(null); 1143 FileStatus[] logfiles = fs.listStatus(WALDIR); 1144 assertTrue("There should be some log file", 1145 logfiles != null && logfiles.length > 0); 1146 1147 WALSplitter logSplitter = new WALSplitter(wals, conf, HBASEDIR, fs, null, null) { 1148 @Override 1149 protected Writer createWriter(Path logfile) 1150 throws IOException { 1151 Writer writer = wals.createRecoveredEditsWriter(this.walFS, logfile); 1152 // After creating writer, simulate region's 1153 // replayRecoveredEditsIfAny() which gets SplitEditFiles of this 1154 // region and delete them, excluding files with '.temp' suffix. 1155 NavigableSet<Path> files = WALSplitter.getSplitEditFilesSorted(fs, regiondir); 1156 if (files != null && !files.isEmpty()) { 1157 for (Path file : files) { 1158 if (!this.walFS.delete(file, false)) { 1159 LOG.error("Failed delete of " + file); 1160 } else { 1161 LOG.debug("Deleted recovered.edits file=" + file); 1162 } 1163 } 1164 } 1165 return writer; 1166 } 1167 }; 1168 try{ 1169 logSplitter.splitLogFile(logfiles[0], null); 1170 } catch (IOException e) { 1171 LOG.info(e.toString(), e); 1172 fail("Throws IOException when spliting " 1173 + "log, it is most likely because writing file does not " 1174 + "exist which is caused by concurrent replayRecoveredEditsIfAny()"); 1175 } 1176 if (fs.exists(CORRUPTDIR)) { 1177 if (fs.listStatus(CORRUPTDIR).length > 0) { 1178 fail("There are some corrupt logs, " 1179 + "it is most likely caused by concurrent replayRecoveredEditsIfAny()"); 1180 } 1181 } 1182 } 1183 1184 private Writer generateWALs(int leaveOpen) throws IOException { 1185 return generateWALs(NUM_WRITERS, ENTRIES, leaveOpen, 0); 1186 } 1187 1188 private Writer generateWALs(int writers, int entries, int leaveOpen) throws IOException { 1189 return generateWALs(writers, entries, leaveOpen, 7); 1190 } 1191 1192 private void makeRegionDirs(List<String> regions) throws IOException { 1193 for (String region : regions) { 1194 LOG.debug("Creating dir for region " + region); 1195 fs.mkdirs(new Path(TABLEDIR, region)); 1196 } 1197 } 1198 1199 /** 1200 * @param leaveOpen index to leave un-closed. -1 to close all. 1201 * @return the writer that's still open, or null if all were closed. 1202 */ 1203 private Writer generateWALs(int writers, int entries, int leaveOpen, int regionEvents) throws IOException { 1204 makeRegionDirs(REGIONS); 1205 fs.mkdirs(WALDIR); 1206 Writer [] ws = new Writer[writers]; 1207 int seq = 0; 1208 int numRegionEventsAdded = 0; 1209 for (int i = 0; i < writers; i++) { 1210 ws[i] = wals.createWALWriter(fs, new Path(WALDIR, WAL_FILE_PREFIX + i)); 1211 for (int j = 0; j < entries; j++) { 1212 int prefix = 0; 1213 for (String region : REGIONS) { 1214 String row_key = region + prefix++ + i + j; 1215 appendEntry(ws[i], TABLE_NAME, Bytes.toBytes(region), Bytes.toBytes(row_key), FAMILY, 1216 QUALIFIER, VALUE, seq++); 1217 1218 if (numRegionEventsAdded < regionEvents) { 1219 numRegionEventsAdded ++; 1220 appendRegionEvent(ws[i], region); 1221 } 1222 } 1223 } 1224 if (i != leaveOpen) { 1225 ws[i].close(); 1226 LOG.info("Closing writer " + i); 1227 } 1228 } 1229 if (leaveOpen < 0 || leaveOpen >= writers) { 1230 return null; 1231 } 1232 return ws[leaveOpen]; 1233 } 1234 1235 1236 1237 private Path[] getLogForRegion(TableName table, String region) 1238 throws IOException { 1239 Path tdir = FSUtils.getWALTableDir(conf, table); 1240 @SuppressWarnings("deprecation") 1241 Path editsdir = WALSplitter.getRegionDirRecoveredEditsDir(HRegion.getRegionDir(tdir, 1242 Bytes.toString(Bytes.toBytes(region)))); 1243 FileStatus[] files = fs.listStatus(editsdir, new PathFilter() { 1244 @Override 1245 public boolean accept(Path p) { 1246 if (WALSplitter.isSequenceIdFile(p)) { 1247 return false; 1248 } 1249 return true; 1250 } 1251 }); 1252 Path[] paths = new Path[files.length]; 1253 for (int i = 0; i < files.length; i++) { 1254 paths[i] = files[i].getPath(); 1255 } 1256 return paths; 1257 } 1258 1259 private void corruptWAL(Path path, Corruptions corruption, boolean close) throws IOException { 1260 FSDataOutputStream out; 1261 int fileSize = (int) fs.listStatus(path)[0].getLen(); 1262 1263 FSDataInputStream in = fs.open(path); 1264 byte[] corrupted_bytes = new byte[fileSize]; 1265 in.readFully(0, corrupted_bytes, 0, fileSize); 1266 in.close(); 1267 1268 switch (corruption) { 1269 case APPEND_GARBAGE: 1270 fs.delete(path, false); 1271 out = fs.create(path); 1272 out.write(corrupted_bytes); 1273 out.write(Bytes.toBytes("-----")); 1274 closeOrFlush(close, out); 1275 break; 1276 1277 case INSERT_GARBAGE_ON_FIRST_LINE: 1278 fs.delete(path, false); 1279 out = fs.create(path); 1280 out.write(0); 1281 out.write(corrupted_bytes); 1282 closeOrFlush(close, out); 1283 break; 1284 1285 case INSERT_GARBAGE_IN_THE_MIDDLE: 1286 fs.delete(path, false); 1287 out = fs.create(path); 1288 int middle = (int) Math.floor(corrupted_bytes.length / 2); 1289 out.write(corrupted_bytes, 0, middle); 1290 out.write(0); 1291 out.write(corrupted_bytes, middle, corrupted_bytes.length - middle); 1292 closeOrFlush(close, out); 1293 break; 1294 1295 case TRUNCATE: 1296 fs.delete(path, false); 1297 out = fs.create(path); 1298 out.write(corrupted_bytes, 0, fileSize 1299 - (32 + ProtobufLogReader.PB_WAL_COMPLETE_MAGIC.length + Bytes.SIZEOF_INT)); 1300 closeOrFlush(close, out); 1301 break; 1302 1303 case TRUNCATE_TRAILER: 1304 fs.delete(path, false); 1305 out = fs.create(path); 1306 out.write(corrupted_bytes, 0, fileSize - Bytes.SIZEOF_INT);// trailer is truncated. 1307 closeOrFlush(close, out); 1308 break; 1309 } 1310 } 1311 1312 private void closeOrFlush(boolean close, FSDataOutputStream out) 1313 throws IOException { 1314 if (close) { 1315 out.close(); 1316 } else { 1317 Method syncMethod = null; 1318 try { 1319 syncMethod = out.getClass().getMethod("hflush", new Class<?> []{}); 1320 } catch (NoSuchMethodException e) { 1321 try { 1322 syncMethod = out.getClass().getMethod("sync", new Class<?> []{}); 1323 } catch (NoSuchMethodException ex) { 1324 throw new IOException("This version of Hadoop supports " + 1325 "neither Syncable.sync() nor Syncable.hflush()."); 1326 } 1327 } 1328 try { 1329 syncMethod.invoke(out, new Object[]{}); 1330 } catch (Exception e) { 1331 throw new IOException(e); 1332 } 1333 // Not in 0out.hflush(); 1334 } 1335 } 1336 1337 private int countWAL(Path log) throws IOException { 1338 int count = 0; 1339 Reader in = wals.createReader(fs, log); 1340 while (in.next() != null) { 1341 count++; 1342 } 1343 in.close(); 1344 return count; 1345 } 1346 1347 private static void appendCompactionEvent(Writer w, RegionInfo hri, String[] inputs, 1348 String output) throws IOException { 1349 WALProtos.CompactionDescriptor.Builder desc = WALProtos.CompactionDescriptor.newBuilder(); 1350 desc.setTableName(ByteString.copyFrom(hri.getTable().toBytes())) 1351 .setEncodedRegionName(ByteString.copyFrom(hri.getEncodedNameAsBytes())) 1352 .setRegionName(ByteString.copyFrom(hri.getRegionName())) 1353 .setFamilyName(ByteString.copyFrom(FAMILY)) 1354 .setStoreHomeDir(hri.getEncodedName() + "/" + Bytes.toString(FAMILY)) 1355 .addAllCompactionInput(Arrays.asList(inputs)) 1356 .addCompactionOutput(output); 1357 1358 WALEdit edit = WALEdit.createCompaction(hri, desc.build()); 1359 WALKeyImpl key = new WALKeyImpl(hri.getEncodedNameAsBytes(), TABLE_NAME, 1, 1360 EnvironmentEdgeManager.currentTime(), HConstants.DEFAULT_CLUSTER_ID); 1361 w.append(new Entry(key, edit)); 1362 w.sync(); 1363 } 1364 1365 private static void appendRegionEvent(Writer w, String region) throws IOException { 1366 WALProtos.RegionEventDescriptor regionOpenDesc = ProtobufUtil.toRegionEventDescriptor( 1367 WALProtos.RegionEventDescriptor.EventType.REGION_OPEN, 1368 TABLE_NAME.toBytes(), 1369 Bytes.toBytes(region), 1370 Bytes.toBytes(String.valueOf(region.hashCode())), 1371 1, 1372 ServerName.parseServerName("ServerName:9099"), ImmutableMap.<byte[], List<Path>>of()); 1373 final long time = EnvironmentEdgeManager.currentTime(); 1374 KeyValue kv = new KeyValue(Bytes.toBytes(region), WALEdit.METAFAMILY, WALEdit.REGION_EVENT, 1375 time, regionOpenDesc.toByteArray()); 1376 final WALKeyImpl walKey = new WALKeyImpl(Bytes.toBytes(region), TABLE_NAME, 1, time, 1377 HConstants.DEFAULT_CLUSTER_ID); 1378 w.append( 1379 new Entry(walKey, new WALEdit().add(kv))); 1380 w.sync(); 1381 } 1382 1383 public static long appendEntry(Writer writer, TableName table, byte[] region, 1384 byte[] row, byte[] family, byte[] qualifier, 1385 byte[] value, long seq) 1386 throws IOException { 1387 LOG.info(Thread.currentThread().getName() + " append"); 1388 writer.append(createTestEntry(table, region, row, family, qualifier, value, seq)); 1389 LOG.info(Thread.currentThread().getName() + " sync"); 1390 writer.sync(); 1391 return seq; 1392 } 1393 1394 private static Entry createTestEntry( 1395 TableName table, byte[] region, 1396 byte[] row, byte[] family, byte[] qualifier, 1397 byte[] value, long seq) { 1398 long time = System.nanoTime(); 1399 1400 seq++; 1401 final KeyValue cell = new KeyValue(row, family, qualifier, time, KeyValue.Type.Put, value); 1402 WALEdit edit = new WALEdit(); 1403 edit.add(cell); 1404 return new Entry(new WALKeyImpl(region, table, seq, time, 1405 HConstants.DEFAULT_CLUSTER_ID), edit); 1406 } 1407 1408 private void injectEmptyFile(String suffix, boolean closeFile) throws IOException { 1409 Writer writer = 1410 WALFactory.createWALWriter(fs, new Path(WALDIR, WAL_FILE_PREFIX + suffix), conf); 1411 if (closeFile) { 1412 writer.close(); 1413 } 1414 } 1415 1416 private boolean logsAreEqual(Path p1, Path p2) throws IOException { 1417 Reader in1, in2; 1418 in1 = wals.createReader(fs, p1); 1419 in2 = wals.createReader(fs, p2); 1420 Entry entry1; 1421 Entry entry2; 1422 while ((entry1 = in1.next()) != null) { 1423 entry2 = in2.next(); 1424 if ((entry1.getKey().compareTo(entry2.getKey()) != 0) || 1425 (!entry1.getEdit().toString().equals(entry2.getEdit().toString()))) { 1426 return false; 1427 } 1428 } 1429 in1.close(); 1430 in2.close(); 1431 return true; 1432 } 1433}