/** * Copyright 2011 The Apache Software Foundation * * Licensed to the Apache Software Foundation (ASF) under one * or more contributor license agreements. See the NOTICE file * distributed with this work for additional information * regarding copyright ownership. The ASF licenses this file * to you under the Apache License, Version 2.0 (the * "License"); you may not use this file except in compliance * with the License. You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ package org.apache.hadoop.hbase.regionserver.wal; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertFalse; import static org.junit.Assert.assertNotNull; import static org.junit.Assert.assertTrue; import static org.junit.Assert.fail; import java.io.FileNotFoundException; import java.io.IOException; import java.lang.reflect.Method; import java.util.ArrayList; import java.util.Collections; import java.util.List; import java.util.Map; import java.util.NavigableSet; import java.util.concurrent.CountDownLatch; import java.util.concurrent.atomic.AtomicBoolean; import java.util.concurrent.atomic.AtomicLong; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; import org.apache.hadoop.conf.Configuration; import org.apache.hadoop.fs.FSDataInputStream; import org.apache.hadoop.fs.FSDataOutputStream; import org.apache.hadoop.fs.FileStatus; import org.apache.hadoop.fs.FileSystem; import org.apache.hadoop.fs.FileUtil; import org.apache.hadoop.fs.Path; import org.apache.hadoop.hbase.HBaseTestingUtility; import org.apache.hadoop.hbase.HColumnDescriptor; import org.apache.hadoop.hbase.HConstants; import org.apache.hadoop.hbase.HRegionInfo; import org.apache.hadoop.hbase.HTableDescriptor; import org.apache.hadoop.hbase.KeyValue; import org.apache.hadoop.hbase.LargeTests; import org.apache.hadoop.hbase.regionserver.HRegion; import org.apache.hadoop.hbase.regionserver.wal.HLog.Entry; import org.apache.hadoop.hbase.regionserver.wal.HLog.Reader; import org.apache.hadoop.hbase.util.Bytes; import org.apache.hadoop.hbase.util.CancelableProgressable; import org.apache.hadoop.hbase.util.Threads; import org.apache.hadoop.hdfs.server.namenode.LeaseExpiredException; import org.apache.hadoop.ipc.RemoteException; import org.junit.After; import org.junit.AfterClass; import org.junit.Assert; import org.junit.Before; import org.junit.BeforeClass; import org.junit.Ignore; import org.junit.Test; import org.junit.experimental.categories.Category; import org.mockito.Mockito; import org.mockito.invocation.InvocationOnMock; import org.mockito.stubbing.Answer; import com.google.common.base.Joiner; import com.google.common.collect.ImmutableList; /** * Testing {@link HLog} splitting code. */ @Category(LargeTests.class) public class TestHLogSplit { private final static Log LOG = LogFactory.getLog(TestHLogSplit.class); private Configuration conf; private FileSystem fs; protected final static HBaseTestingUtility TEST_UTIL = new HBaseTestingUtility(); private static final Path hbaseDir = new Path("/hbase"); private static final Path hlogDir = new Path(hbaseDir, "hlog"); private static final Path oldLogDir = new Path(hbaseDir, "hlog.old"); private static final Path corruptDir = new Path(hbaseDir, ".corrupt"); private static final int NUM_WRITERS = 10; private static final int ENTRIES = 10; // entries per writer per region private HLog.Writer[] writer = new HLog.Writer[NUM_WRITERS]; private long seq = 0; private static final byte[] TABLE_NAME = "t1".getBytes(); private static final byte[] FAMILY = "f1".getBytes(); private static final byte[] QUALIFIER = "q1".getBytes(); private static final byte[] VALUE = "v1".getBytes(); private static final String HLOG_FILE_PREFIX = "hlog.dat."; private static List<String> regions; private static final String HBASE_SKIP_ERRORS = "hbase.hlog.split.skip.errors"; private static final Path tabledir = new Path(hbaseDir, Bytes.toString(TABLE_NAME)); static enum Corruptions { INSERT_GARBAGE_ON_FIRST_LINE, INSERT_GARBAGE_IN_THE_MIDDLE, APPEND_GARBAGE, TRUNCATE, } @BeforeClass public static void setUpBeforeClass() throws Exception { TEST_UTIL.getConfiguration().setStrings("hbase.rootdir", hbaseDir.toString()); TEST_UTIL.getConfiguration().setClass("hbase.regionserver.hlog.writer.impl", InstrumentedSequenceFileLogWriter.class, HLog.Writer.class); TEST_UTIL.getConfiguration().setBoolean("dfs.support.broken.append", true); TEST_UTIL.getConfiguration().setBoolean("dfs.support.append", true); TEST_UTIL.startMiniDFSCluster(2); } @AfterClass public static void tearDownAfterClass() throws Exception { TEST_UTIL.shutdownMiniDFSCluster(); } @Before public void setUp() throws Exception { flushToConsole("Cleaning up cluster for new test\n" + "--------------------------"); conf = TEST_UTIL.getConfiguration(); fs = TEST_UTIL.getDFSCluster().getFileSystem(); FileStatus[] entries = fs.listStatus(new Path("/")); flushToConsole("Num entries in /:" + entries.length); for (FileStatus dir : entries){ assertTrue("Deleting " + dir.getPath(), fs.delete(dir.getPath(), true)); } // create the HLog directory because recursive log creates are not allowed fs.mkdirs(hlogDir); seq = 0; regions = new ArrayList<String>(); Collections.addAll(regions, "bbb", "ccc"); InstrumentedSequenceFileLogWriter.activateFailure = false; } @After public void tearDown() throws Exception { } /** * @throws IOException * @see https://issues.apache.org/jira/browse/HBASE-3020 */ @Test public void testRecoveredEditsPathForMeta() throws IOException { FileSystem fs = FileSystem.get(TEST_UTIL.getConfiguration()); byte [] encoded = HRegionInfo.FIRST_META_REGIONINFO.getEncodedNameAsBytes(); Path tdir = new Path(hbaseDir, Bytes.toString(HConstants.META_TABLE_NAME)); Path regiondir = new Path(tdir, HRegionInfo.FIRST_META_REGIONINFO.getEncodedName()); fs.mkdirs(regiondir); long now = System.currentTimeMillis(); HLog.Entry entry = new HLog.Entry(new HLogKey(encoded, HConstants.META_TABLE_NAME, 1, now, HConstants.DEFAULT_CLUSTER_ID), new WALEdit()); Path p = HLogSplitter.getRegionSplitEditsPath(fs, entry, hbaseDir, true); String parentOfParent = p.getParent().getParent().getName(); assertEquals(parentOfParent, HRegionInfo.FIRST_META_REGIONINFO.getEncodedName()); } @Test(expected = OrphanHLogAfterSplitException.class) public void testSplitFailsIfNewHLogGetsCreatedAfterSplitStarted() throws IOException { AtomicBoolean stop = new AtomicBoolean(false); assertFalse("Previous test should clean up table dir", fs.exists(new Path("/hbase/t1"))); generateHLogs(-1); CountDownLatch latch = new CountDownLatch(1); try { (new ZombieNewLogWriterRegionServer(latch, stop)).start(); HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(latch); } finally { stop.set(true); } } @Test public void testSplitPreservesEdits() throws IOException{ final String REGION = "region__1"; regions.removeAll(regions); regions.add(REGION); generateHLogs(1, 10, -1); fs.initialize(fs.getUri(), conf); HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(); Path originalLog = (fs.listStatus(oldLogDir))[0].getPath(); Path splitLog = getLogForRegion(hbaseDir, TABLE_NAME, REGION); assertEquals("edits differ after split", true, logsAreEqual(originalLog, splitLog)); } @Test public void testEmptyLogFiles() throws IOException { injectEmptyFile(".empty", true); generateHLogs(Integer.MAX_VALUE); injectEmptyFile("empty", true); // make fs act as a different client now // initialize will create a new DFSClient with a new client ID fs.initialize(fs.getUri(), conf); HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(); for (String region : regions) { Path logfile = getLogForRegion(hbaseDir, TABLE_NAME, region); assertEquals(NUM_WRITERS * ENTRIES, countHLog(logfile, fs, conf)); } } @Test public void testEmptyOpenLogFiles() throws IOException { injectEmptyFile(".empty", false); generateHLogs(Integer.MAX_VALUE); injectEmptyFile("empty", false); // make fs act as a different client now // initialize will create a new DFSClient with a new client ID fs.initialize(fs.getUri(), conf); HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(); for (String region : regions) { Path logfile = getLogForRegion(hbaseDir, TABLE_NAME, region); assertEquals(NUM_WRITERS * ENTRIES, countHLog(logfile, fs, conf)); } } @Test public void testOpenZeroLengthReportedFileButWithDataGetsSplit() throws IOException { // generate logs but leave hlog.dat.5 open. generateHLogs(5); fs.initialize(fs.getUri(), conf); HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(); for (String region : regions) { Path logfile = getLogForRegion(hbaseDir, TABLE_NAME, region); assertEquals(NUM_WRITERS * ENTRIES, countHLog(logfile, fs, conf)); } } @Test public void testTralingGarbageCorruptionFileSkipErrorsPasses() throws IOException { conf.setBoolean(HBASE_SKIP_ERRORS, true); generateHLogs(Integer.MAX_VALUE); corruptHLog(new Path(hlogDir, HLOG_FILE_PREFIX + "5"), Corruptions.APPEND_GARBAGE, true, fs); fs.initialize(fs.getUri(), conf); HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(); for (String region : regions) { Path logfile = getLogForRegion(hbaseDir, TABLE_NAME, region); assertEquals(NUM_WRITERS * ENTRIES, countHLog(logfile, fs, conf)); } } @Test public void testFirstLineCorruptionLogFileSkipErrorsPasses() throws IOException { conf.setBoolean(HBASE_SKIP_ERRORS, true); generateHLogs(Integer.MAX_VALUE); corruptHLog(new Path(hlogDir, HLOG_FILE_PREFIX + "5"), Corruptions.INSERT_GARBAGE_ON_FIRST_LINE, true, fs); fs.initialize(fs.getUri(), conf); HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(); for (String region : regions) { Path logfile = getLogForRegion(hbaseDir, TABLE_NAME, region); assertEquals((NUM_WRITERS - 1) * ENTRIES, countHLog(logfile, fs, conf)); } } @Test public void testMiddleGarbageCorruptionSkipErrorsReadsHalfOfFile() throws IOException { conf.setBoolean(HBASE_SKIP_ERRORS, true); generateHLogs(Integer.MAX_VALUE); corruptHLog(new Path(hlogDir, HLOG_FILE_PREFIX + "5"), Corruptions.INSERT_GARBAGE_IN_THE_MIDDLE, false, fs); fs.initialize(fs.getUri(), conf); HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(); for (String region : regions) { Path logfile = getLogForRegion(hbaseDir, TABLE_NAME, region); // the entries in the original logs are alternating regions // considering the sequence file header, the middle corruption should // affect at least half of the entries int goodEntries = (NUM_WRITERS - 1) * ENTRIES; int firstHalfEntries = (int) Math.ceil(ENTRIES / 2) - 1; assertTrue("The file up to the corrupted area hasn't been parsed", goodEntries + firstHalfEntries <= countHLog(logfile, fs, conf)); } } @Test public void testCorruptedFileGetsArchivedIfSkipErrors() throws IOException { conf.setBoolean(HBASE_SKIP_ERRORS, true); Class<?> backupClass = conf.getClass("hbase.regionserver.hlog.reader.impl", Reader.class); InstrumentedSequenceFileLogWriter.activateFailure = false; HLog.resetLogReaderClass(); try { Path c1 = new Path(hlogDir, HLOG_FILE_PREFIX + "0"); conf.setClass("hbase.regionserver.hlog.reader.impl", FaultySequenceFileLogReader.class, HLog.Reader.class); for (FaultySequenceFileLogReader.FailureType failureType : FaultySequenceFileLogReader.FailureType.values()) { conf.set("faultysequencefilelogreader.failuretype", failureType.name()); generateHLogs(1, ENTRIES, -1); fs.initialize(fs.getUri(), conf); HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(); FileStatus[] archivedLogs = fs.listStatus(corruptDir); assertEquals("expected a different file", c1.getName(), archivedLogs[0] .getPath().getName()); assertEquals(archivedLogs.length, 1); fs.delete(new Path(oldLogDir, HLOG_FILE_PREFIX + "0"), false); } } finally { conf.setClass("hbase.regionserver.hlog.reader.impl", backupClass, Reader.class); HLog.resetLogReaderClass(); } } @Test(expected = IOException.class) public void testTrailingGarbageCorruptionLogFileSkipErrorsFalseThrows() throws IOException { conf.setBoolean(HBASE_SKIP_ERRORS, false); Class<?> backupClass = conf.getClass("hbase.regionserver.hlog.reader.impl", Reader.class); InstrumentedSequenceFileLogWriter.activateFailure = false; HLog.resetLogReaderClass(); try { conf.setClass("hbase.regionserver.hlog.reader.impl", FaultySequenceFileLogReader.class, HLog.Reader.class); conf.set("faultysequencefilelogreader.failuretype", FaultySequenceFileLogReader.FailureType.BEGINNING.name()); generateHLogs(Integer.MAX_VALUE); fs.initialize(fs.getUri(), conf); HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(); } finally { conf.setClass("hbase.regionserver.hlog.reader.impl", backupClass, Reader.class); HLog.resetLogReaderClass(); } } @Test public void testCorruptedLogFilesSkipErrorsFalseDoesNotTouchLogs() throws IOException { conf.setBoolean(HBASE_SKIP_ERRORS, false); Class<?> backupClass = conf.getClass("hbase.regionserver.hlog.reader.impl", Reader.class); InstrumentedSequenceFileLogWriter.activateFailure = false; HLog.resetLogReaderClass(); try { conf.setClass("hbase.regionserver.hlog.reader.impl", FaultySequenceFileLogReader.class, HLog.Reader.class); conf.set("faultysequencefilelogreader.failuretype", FaultySequenceFileLogReader.FailureType.BEGINNING.name()); generateHLogs(-1); fs.initialize(fs.getUri(), conf); HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); try { logSplitter.splitLog(); } catch (IOException e) { assertEquals( "if skip.errors is false all files should remain in place", NUM_WRITERS, fs.listStatus(hlogDir).length); } } finally { conf.setClass("hbase.regionserver.hlog.reader.impl", backupClass, Reader.class); HLog.resetLogReaderClass(); } } @Test public void testEOFisIgnored() throws IOException { conf.setBoolean(HBASE_SKIP_ERRORS, false); final String REGION = "region__1"; regions.removeAll(regions); regions.add(REGION); int entryCount = 10; Path c1 = new Path(hlogDir, HLOG_FILE_PREFIX + "0"); generateHLogs(1, entryCount, -1); corruptHLog(c1, Corruptions.TRUNCATE, true, fs); fs.initialize(fs.getUri(), conf); HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(); Path originalLog = (fs.listStatus(oldLogDir))[0].getPath(); Path splitLog = getLogForRegion(hbaseDir, TABLE_NAME, REGION); int actualCount = 0; HLog.Reader in = HLog.getReader(fs, splitLog, conf); HLog.Entry entry; while ((entry = in.next()) != null) ++actualCount; assertEquals(entryCount-1, actualCount); // should not have stored the EOF files as corrupt FileStatus[] archivedLogs = fs.listStatus(corruptDir); assertEquals(archivedLogs.length, 0); } @Test public void testLogsGetArchivedAfterSplit() throws IOException { conf.setBoolean(HBASE_SKIP_ERRORS, false); generateHLogs(-1); fs.initialize(fs.getUri(), conf); HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(); FileStatus[] archivedLogs = fs.listStatus(oldLogDir); assertEquals("wrong number of files in the archive log", NUM_WRITERS, archivedLogs.length); } @Test public void testSplit() throws IOException { generateHLogs(-1); fs.initialize(fs.getUri(), conf); HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(); for (String region : regions) { Path logfile = getLogForRegion(hbaseDir, TABLE_NAME, region); assertEquals(NUM_WRITERS * ENTRIES, countHLog(logfile, fs, conf)); } } @Test public void testLogDirectoryShouldBeDeletedAfterSuccessfulSplit() throws IOException { generateHLogs(-1); fs.initialize(fs.getUri(), conf); HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(); FileStatus [] statuses = null; try { statuses = fs.listStatus(hlogDir); if (statuses != null) { Assert.fail("Files left in log dir: " + Joiner.on(",").join(FileUtil.stat2Paths(statuses))); } } catch (FileNotFoundException e) { // hadoop 0.21 throws FNFE whereas hadoop 0.20 returns null } } /* DISABLED for now. TODO: HBASE-2645 @Test public void testLogCannotBeWrittenOnceParsed() throws IOException { AtomicLong counter = new AtomicLong(0); AtomicBoolean stop = new AtomicBoolean(false); generateHLogs(9); fs.initialize(fs.getUri(), conf); Thread zombie = new ZombieLastLogWriterRegionServer(writer[9], counter, stop); try { zombie.start(); HLog.splitLog(hbaseDir, hlogDir, oldLogDir, fs, conf); Path logfile = getLogForRegion(hbaseDir, TABLE_NAME, "juliet"); // It's possible that the writer got an error while appending and didn't count it // however the entry will in fact be written to file and split with the rest long numberOfEditsInRegion = countHLog(logfile, fs, conf); assertTrue("The log file could have at most 1 extra log entry, but " + "can't have less. Zombie could write "+counter.get() +" and logfile had only"+ numberOfEditsInRegion+" " + logfile, counter.get() == numberOfEditsInRegion || counter.get() + 1 == numberOfEditsInRegion); } finally { stop.set(true); } } */ @Test public void testSplitWillNotTouchLogsIfNewHLogGetsCreatedAfterSplitStarted() throws IOException { AtomicBoolean stop = new AtomicBoolean(false); generateHLogs(-1); fs.initialize(fs.getUri(), conf); CountDownLatch latch = new CountDownLatch(1); Thread zombie = new ZombieNewLogWriterRegionServer(latch, stop); List<Path> splits = null; try { zombie.start(); try { HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); splits = logSplitter.splitLog(latch); } catch (IOException ex) { /* expected */ LOG.warn("testSplitWillNotTouchLogsIfNewHLogGetsCreatedAfterSplitStarted", ex); } FileStatus[] files = fs.listStatus(hlogDir); if (files == null) fail("no files in " + hlogDir + " with splits " + splits); int logFilesNumber = files.length; assertEquals("Log files should not be archived if there's an extra file after split", NUM_WRITERS + 1, logFilesNumber); } finally { stop.set(true); } } @Test(expected = IOException.class) public void testSplitWillFailIfWritingToRegionFails() throws Exception { //leave 5th log open so we could append the "trap" generateHLogs(4); fs.initialize(fs.getUri(), conf); String region = "break"; Path regiondir = new Path(tabledir, region); fs.mkdirs(regiondir); InstrumentedSequenceFileLogWriter.activateFailure = false; appendEntry(writer[4], TABLE_NAME, Bytes.toBytes(region), ("r" + 999).getBytes(), FAMILY, QUALIFIER, VALUE, 0); writer[4].close(); try { InstrumentedSequenceFileLogWriter.activateFailure = true; HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(); } catch (IOException e) { assertEquals("This exception is instrumented and should only be thrown for testing", e.getMessage()); throw e; } finally { InstrumentedSequenceFileLogWriter.activateFailure = false; } } // @Test TODO this test has been disabled since it was created! // It currently fails because the second split doesn't output anything // -- because there are no region dirs after we move aside the first // split result public void testSplittingLargeNumberOfRegionsConsistency() throws IOException { regions.removeAll(regions); for (int i=0; i<100; i++) { regions.add("region__"+i); } generateHLogs(1, 100, -1); fs.initialize(fs.getUri(), conf); HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(); fs.rename(oldLogDir, hlogDir); Path firstSplitPath = new Path(hbaseDir, Bytes.toString(TABLE_NAME) + ".first"); Path splitPath = new Path(hbaseDir, Bytes.toString(TABLE_NAME)); fs.rename(splitPath, firstSplitPath); fs.initialize(fs.getUri(), conf); logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(); assertEquals(0, compareHLogSplitDirs(firstSplitPath, splitPath)); } @Test public void testSplitDeletedRegion() throws IOException { regions.removeAll(regions); String region = "region_that_splits"; regions.add(region); generateHLogs(1); fs.initialize(fs.getUri(), conf); Path regiondir = new Path(tabledir, region); fs.delete(regiondir, true); HLogSplitter logSplitter = HLogSplitter.createLogSplitter(conf, hbaseDir, hlogDir, oldLogDir, fs); logSplitter.splitLog(); assertFalse(fs.exists(regiondir)); } @Test public void testIOEOnOutputThread() throws Exception { conf.setBoolean(HBASE_SKIP_ERRORS, false); generateHLogs(-1); fs.initialize(fs.getUri(), conf); // Set up a splitter that will throw an IOE on the output side HLogSplitter logSplitter = new HLogSplitter( conf, hbaseDir, hlogDir, oldLogDir, fs) { protected HLog.Writer createWriter(FileSystem fs, Path logfile, Configuration conf) throws IOException { HLog.Writer mockWriter = Mockito.mock(HLog.Writer.class); Mockito.doThrow(new IOException("Injected")).when(mockWriter).append(Mockito.<HLog.Entry>any()); return mockWriter; } }; try { logSplitter.splitLog(); fail("Didn't throw!"); } catch (IOException ioe) { assertTrue(ioe.toString().contains("Injected")); } } // Test for HBASE-3412 @Test public void testMovedHLogDuringRecovery() throws Exception { generateHLogs(-1); fs.initialize(fs.getUri(), conf); // This partial mock will throw LEE for every file simulating // files that were moved FileSystem spiedFs = Mockito.spy(fs); // The "File does not exist" part is very important, // that's how it comes out of HDFS Mockito.doThrow(new LeaseExpiredException("Injected: File does not exist")). when(spiedFs).append(Mockito.<Path>any()); HLogSplitter logSplitter = new HLogSplitter( conf, hbaseDir, hlogDir, oldLogDir, spiedFs); try { logSplitter.splitLog(); assertEquals(NUM_WRITERS, fs.listStatus(oldLogDir).length); assertFalse(fs.exists(hlogDir)); } catch (IOException e) { fail("There shouldn't be any exception but: " + e.toString()); } } /** * Test log split process with fake data and lots of edits to trigger threading * issues. */ @Test public void testThreading() throws Exception { doTestThreading(20000, 128*1024*1024, 0); } /** * Test blocking behavior of the log split process if writers are writing slower * than the reader is reading. */ @Test public void testThreadingSlowWriterSmallBuffer() throws Exception { doTestThreading(200, 1024, 50); } /** * Sets up a log splitter with a mock reader and writer. The mock reader generates * a specified number of edits spread across 5 regions. The mock writer optionally * sleeps for each edit it is fed. * * * After the split is complete, verifies that the statistics show the correct number * of edits output into each region. * * @param numFakeEdits number of fake edits to push through pipeline * @param bufferSize size of in-memory buffer * @param writerSlowness writer threads will sleep this many ms per edit */ private void doTestThreading(final int numFakeEdits, final int bufferSize, final int writerSlowness) throws Exception { Configuration localConf = new Configuration(conf); localConf.setInt("hbase.regionserver.hlog.splitlog.buffersize", bufferSize); // Create a fake log file (we'll override the reader to produce a stream of edits) FSDataOutputStream out = fs.create(new Path(hlogDir, HLOG_FILE_PREFIX + ".fake")); out.close(); // Make region dirs for our destination regions so the output doesn't get skipped final List<String> regions = ImmutableList.of("r0", "r1", "r2", "r3", "r4"); makeRegionDirs(fs, regions); // Create a splitter that reads and writes the data without touching disk HLogSplitter logSplitter = new HLogSplitter( localConf, hbaseDir, hlogDir, oldLogDir, fs) { /* Produce a mock writer that doesn't write anywhere */ protected HLog.Writer createWriter(FileSystem fs, Path logfile, Configuration conf) throws IOException { HLog.Writer mockWriter = Mockito.mock(HLog.Writer.class); Mockito.doAnswer(new Answer<Void>() { int expectedIndex = 0; @Override public Void answer(InvocationOnMock invocation) { if (writerSlowness > 0) { try { Thread.sleep(writerSlowness); } catch (InterruptedException ie) { Thread.currentThread().interrupt(); } } HLog.Entry entry = (Entry) invocation.getArguments()[0]; WALEdit edit = entry.getEdit(); List<KeyValue> keyValues = edit.getKeyValues(); assertEquals(1, keyValues.size()); KeyValue kv = keyValues.get(0); // Check that the edits come in the right order. assertEquals(expectedIndex, Bytes.toInt(kv.getRow())); expectedIndex++; return null; } }).when(mockWriter).append(Mockito.<HLog.Entry>any()); return mockWriter; } /* Produce a mock reader that generates fake entries */ protected Reader getReader(FileSystem fs, Path curLogFile, Configuration conf) throws IOException { Reader mockReader = Mockito.mock(Reader.class); Mockito.doAnswer(new Answer<HLog.Entry>() { int index = 0; @Override public HLog.Entry answer(InvocationOnMock invocation) throws Throwable { if (index >= numFakeEdits) return null; // Generate r0 through r4 in round robin fashion int regionIdx = index % regions.size(); byte region[] = new byte[] {(byte)'r', (byte) (0x30 + regionIdx)}; HLog.Entry ret = createTestEntry(TABLE_NAME, region, Bytes.toBytes((int)(index / regions.size())), FAMILY, QUALIFIER, VALUE, index); index++; return ret; } }).when(mockReader).next(); return mockReader; } }; logSplitter.splitLog(); // Verify number of written edits per region Map<byte[], Long> outputCounts = logSplitter.getOutputCounts(); for (Map.Entry<byte[], Long> entry : outputCounts.entrySet()) { LOG.info("Got " + entry.getValue() + " output edits for region " + Bytes.toString(entry.getKey())); assertEquals((long)entry.getValue(), numFakeEdits / regions.size()); } assertEquals(regions.size(), outputCounts.size()); } // HBASE-2312: tests the case where a RegionServer enters a GC pause, // comes back online after the master declared it dead and started to split. // Want log rolling after a master split to fail @Test @Ignore("Need HADOOP-6886, HADOOP-6840, & HDFS-617 for this. HDFS 0.20.205.1+ should have this") public void testLogRollAfterSplitStart() throws IOException { // set flush interval to a large number so it doesn't interrupt us final String F_INTERVAL = "hbase.regionserver.optionallogflushinterval"; long oldFlushInterval = conf.getLong(F_INTERVAL, 1000); conf.setLong(F_INTERVAL, 1000*1000*100); HLog log = null; Path thisTestsDir = new Path(hbaseDir, "testLogRollAfterSplitStart"); try { // put some entries in an HLog byte [] tableName = Bytes.toBytes(this.getClass().getName()); HRegionInfo regioninfo = new HRegionInfo(tableName, HConstants.EMPTY_START_ROW, HConstants.EMPTY_END_ROW); log = new HLog(fs, thisTestsDir, oldLogDir, conf); final int total = 20; for (int i = 0; i < total; i++) { WALEdit kvs = new WALEdit(); kvs.add(new KeyValue(Bytes.toBytes(i), tableName, tableName)); HTableDescriptor htd = new HTableDescriptor(tableName); htd.addFamily(new HColumnDescriptor("column")); log.append(regioninfo, tableName, kvs, System.currentTimeMillis(), htd); } // Send the data to HDFS datanodes and close the HDFS writer log.sync(); log.cleanupCurrentWriter(log.getFilenum()); /* code taken from ProcessServerShutdown.process() * handles RS shutdowns (as observed by the Master) */ // rename the directory so a rogue RS doesn't create more HLogs Path rsSplitDir = new Path(thisTestsDir.getParent(), thisTestsDir.getName() + "-splitting"); fs.rename(thisTestsDir, rsSplitDir); LOG.debug("Renamed region directory: " + rsSplitDir); // Process the old log files HLogSplitter splitter = HLogSplitter.createLogSplitter(conf, hbaseDir, rsSplitDir, oldLogDir, fs); splitter.splitLog(); // Now, try to roll the HLog and verify failure try { log.rollWriter(); Assert.fail("rollWriter() did not throw any exception."); } catch (IOException ioe) { if (ioe.getCause().getMessage().contains("FileNotFound")) { LOG.info("Got the expected exception: ", ioe.getCause()); } else { Assert.fail("Unexpected exception: " + ioe); } } } finally { conf.setLong(F_INTERVAL, oldFlushInterval); if (log != null) { log.close(); } if (fs.exists(thisTestsDir)) { fs.delete(thisTestsDir, true); } } } /** * This thread will keep writing to the file after the split process has started * It simulates a region server that was considered dead but woke up and wrote * some more to he last log entry */ class ZombieLastLogWriterRegionServer extends Thread { AtomicLong editsCount; AtomicBoolean stop; Path log; HLog.Writer lastLogWriter; public ZombieLastLogWriterRegionServer(HLog.Writer writer, AtomicLong counter, AtomicBoolean stop) { this.stop = stop; this.editsCount = counter; this.lastLogWriter = writer; } @Override public void run() { if (stop.get()){ return; } flushToConsole("starting"); while (true) { try { String region = "juliet"; fs.mkdirs(new Path(new Path(hbaseDir, region), region)); appendEntry(lastLogWriter, TABLE_NAME, region.getBytes(), ("r" + editsCount).getBytes(), FAMILY, QUALIFIER, VALUE, 0); lastLogWriter.sync(); editsCount.incrementAndGet(); try { Thread.sleep(1); } catch (InterruptedException e) { // } } catch (IOException ex) { if (ex instanceof RemoteException) { flushToConsole("Juliet: got RemoteException " + ex.getMessage() + " while writing " + (editsCount.get() + 1)); break; } else { assertTrue("Failed to write " + editsCount.get(), false); } } } } } /** * This thread will keep adding new log files * It simulates a region server that was considered dead but woke up and wrote * some more to a new hlog */ class ZombieNewLogWriterRegionServer extends Thread { AtomicBoolean stop; CountDownLatch latch; public ZombieNewLogWriterRegionServer(CountDownLatch latch, AtomicBoolean stop) { super("ZombieNewLogWriterRegionServer"); this.latch = latch; this.stop = stop; } @Override public void run() { if (stop.get()) { return; } Path tableDir = new Path(hbaseDir, new String(TABLE_NAME)); Path regionDir = new Path(tableDir, regions.get(0)); Path recoveredEdits = new Path(regionDir, HLogSplitter.RECOVERED_EDITS); String region = "juliet"; Path julietLog = new Path(hlogDir, HLOG_FILE_PREFIX + ".juliet"); try { while (!fs.exists(recoveredEdits) && !stop.get()) { LOG.info("Juliet: split not started, sleeping a bit..."); Threads.sleep(10); } fs.mkdirs(new Path(tableDir, region)); HLog.Writer writer = HLog.createWriter(fs, julietLog, conf); appendEntry(writer, "juliet".getBytes(), ("juliet").getBytes(), ("r").getBytes(), FAMILY, QUALIFIER, VALUE, 0); writer.close(); LOG.info("Juliet file creator: created file " + julietLog); latch.countDown(); } catch (IOException e1) { LOG.error("Failed to create file " + julietLog, e1); assertTrue("Failed to create file " + julietLog, false); } } } private CancelableProgressable reporter = new CancelableProgressable() { int count = 0; @Override public boolean progress() { count++; LOG.debug("progress = " + count); return true; } }; @Test public void testSplitLogFileWithOneRegion() throws IOException { LOG.info("testSplitLogFileWithOneRegion"); final String REGION = "region__1"; regions.removeAll(regions); regions.add(REGION); generateHLogs(1, 10, -1); FileStatus logfile = fs.listStatus(hlogDir)[0]; fs.initialize(fs.getUri(), conf); HLogSplitter.splitLogFile(hbaseDir, logfile, fs, conf, reporter); HLogSplitter.finishSplitLogFile(hbaseDir, oldLogDir, logfile.getPath() .toString(), conf); Path originalLog = (fs.listStatus(oldLogDir))[0].getPath(); Path splitLog = getLogForRegion(hbaseDir, TABLE_NAME, REGION); assertEquals(true, logsAreEqual(originalLog, splitLog)); } @Test public void testSplitLogFileDeletedRegionDir() throws IOException { LOG.info("testSplitLogFileDeletedRegionDir"); final String REGION = "region__1"; regions.removeAll(regions); regions.add(REGION); generateHLogs(1, 10, -1); FileStatus logfile = fs.listStatus(hlogDir)[0]; fs.initialize(fs.getUri(), conf); Path regiondir = new Path(tabledir, REGION); LOG.info("Region directory is" + regiondir); fs.delete(regiondir, true); HLogSplitter.splitLogFile(hbaseDir, logfile, fs, conf, reporter); HLogSplitter.finishSplitLogFile(hbaseDir, oldLogDir, logfile.getPath() .toString(), conf); assertTrue(!fs.exists(regiondir)); assertTrue(true); } @Test public void testSplitLogFileEmpty() throws IOException { LOG.info("testSplitLogFileEmpty"); injectEmptyFile(".empty", true); FileStatus logfile = fs.listStatus(hlogDir)[0]; fs.initialize(fs.getUri(), conf); HLogSplitter.splitLogFile(hbaseDir, logfile, fs, conf, reporter); HLogSplitter.finishSplitLogFile(hbaseDir, oldLogDir, logfile.getPath() .toString(), conf); Path tdir = HTableDescriptor.getTableDir(hbaseDir, TABLE_NAME); assertFalse(fs.exists(tdir)); assertEquals(0, countHLog(fs.listStatus(oldLogDir)[0].getPath(), fs, conf)); } @Test public void testSplitLogFileMultipleRegions() throws IOException { LOG.info("testSplitLogFileMultipleRegions"); generateHLogs(1, 10, -1); FileStatus logfile = fs.listStatus(hlogDir)[0]; fs.initialize(fs.getUri(), conf); HLogSplitter.splitLogFile(hbaseDir, logfile, fs, conf, reporter); HLogSplitter.finishSplitLogFile(hbaseDir, oldLogDir, logfile.getPath() .toString(), conf); for (String region : regions) { Path recovered = getLogForRegion(hbaseDir, TABLE_NAME, region); assertEquals(10, countHLog(recovered, fs, conf)); } } @Test public void testSplitLogFileFirstLineCorruptionLog() throws IOException { conf.setBoolean(HBASE_SKIP_ERRORS, true); generateHLogs(1, 10, -1); FileStatus logfile = fs.listStatus(hlogDir)[0]; corruptHLog(logfile.getPath(), Corruptions.INSERT_GARBAGE_ON_FIRST_LINE, true, fs); fs.initialize(fs.getUri(), conf); HLogSplitter.splitLogFile(hbaseDir, logfile, fs, conf, reporter); HLogSplitter.finishSplitLogFile(hbaseDir, oldLogDir, logfile.getPath() .toString(), conf); final Path corruptDir = new Path(conf.get(HConstants.HBASE_DIR), conf.get( "hbase.regionserver.hlog.splitlog.corrupt.dir", ".corrupt")); assertEquals(1, fs.listStatus(corruptDir).length); } /** * @throws IOException * @see https://issues.apache.org/jira/browse/HBASE-4862 */ @Test public void testConcurrentSplitLogAndReplayRecoverEdit() throws IOException { LOG.info("testConcurrentSplitLogAndReplayRecoverEdit"); // Generate hlogs for our destination region String regionName = "r0"; final Path regiondir = new Path(tabledir, regionName); regions = new ArrayList<String>(); regions.add(regionName); generateHLogs(-1); HLogSplitter logSplitter = new HLogSplitter( conf, hbaseDir, hlogDir, oldLogDir, fs) { protected HLog.Writer createWriter(FileSystem fs, Path logfile, Configuration conf) throws IOException { HLog.Writer writer = HLog.createWriter(fs, logfile, conf); // After creating writer, simulate region's // replayRecoveredEditsIfAny() which gets SplitEditFiles of this // region and delete them, excluding files with '.temp' suffix. NavigableSet<Path> files = HLog.getSplitEditFilesSorted(this.fs, regiondir); if (files != null && !files.isEmpty()) { for (Path file : files) { if (!this.fs.delete(file, false)) { LOG.error("Failed delete of " + file); } else { LOG.debug("Deleted recovered.edits file=" + file); } } } return writer; } }; try{ logSplitter.splitLog(); } catch (IOException e) { LOG.info(e); Assert.fail("Throws IOException when spliting " + "log, it is most likely because writing file does not " + "exist which is caused by concurrent replayRecoveredEditsIfAny()"); } if (fs.exists(corruptDir)) { if (fs.listStatus(corruptDir).length > 0) { Assert.fail("There are some corrupt logs, " + "it is most likely caused by concurrent replayRecoveredEditsIfAny()"); } } } private void flushToConsole(String s) { System.out.println(s); System.out.flush(); } private void generateHLogs(int leaveOpen) throws IOException { generateHLogs(NUM_WRITERS, ENTRIES, leaveOpen); } private void makeRegionDirs(FileSystem fs, List<String> regions) throws IOException { for (String region : regions) { flushToConsole("Creating dir for region " + region); fs.mkdirs(new Path(tabledir, region)); } } private void generateHLogs(int writers, int entries, int leaveOpen) throws IOException { makeRegionDirs(fs, regions); fs.mkdirs(hlogDir); for (int i = 0; i < writers; i++) { writer[i] = HLog.createWriter(fs, new Path(hlogDir, HLOG_FILE_PREFIX + i), conf); for (int j = 0; j < entries; j++) { int prefix = 0; for (String region : regions) { String row_key = region + prefix++ + i + j; appendEntry(writer[i], TABLE_NAME, region.getBytes(), row_key.getBytes(), FAMILY, QUALIFIER, VALUE, seq); } } if (i != leaveOpen) { writer[i].close(); LOG.info("Closing writer " + i); } } } private Path getLogForRegion(Path rootdir, byte[] table, String region) throws IOException { Path tdir = HTableDescriptor.getTableDir(rootdir, table); Path editsdir = HLog.getRegionDirRecoveredEditsDir(HRegion.getRegionDir(tdir, Bytes.toString(region.getBytes()))); FileStatus [] files = this.fs.listStatus(editsdir); assertEquals(1, files.length); return files[0].getPath(); } private void corruptHLog(Path path, Corruptions corruption, boolean close, FileSystem fs) throws IOException { FSDataOutputStream out; int fileSize = (int) fs.listStatus(path)[0].getLen(); FSDataInputStream in = fs.open(path); byte[] corrupted_bytes = new byte[fileSize]; in.readFully(0, corrupted_bytes, 0, fileSize); in.close(); switch (corruption) { case APPEND_GARBAGE: fs.delete(path, false); out = fs.create(path); out.write(corrupted_bytes); out.write("-----".getBytes()); closeOrFlush(close, out); break; case INSERT_GARBAGE_ON_FIRST_LINE: fs.delete(path, false); out = fs.create(path); out.write(0); out.write(corrupted_bytes); closeOrFlush(close, out); break; case INSERT_GARBAGE_IN_THE_MIDDLE: fs.delete(path, false); out = fs.create(path); int middle = (int) Math.floor(corrupted_bytes.length / 2); out.write(corrupted_bytes, 0, middle); out.write(0); out.write(corrupted_bytes, middle, corrupted_bytes.length - middle); closeOrFlush(close, out); break; case TRUNCATE: fs.delete(path, false); out = fs.create(path); out.write(corrupted_bytes, 0, fileSize-32); closeOrFlush(close, out); break; } } private void closeOrFlush(boolean close, FSDataOutputStream out) throws IOException { if (close) { out.close(); } else { Method syncMethod = null; try { syncMethod = out.getClass().getMethod("hflush", new Class<?> []{}); } catch (NoSuchMethodException e) { try { syncMethod = out.getClass().getMethod("sync", new Class<?> []{}); } catch (NoSuchMethodException ex) { throw new IOException("This version of Hadoop supports " + "neither Syncable.sync() nor Syncable.hflush()."); } } try { syncMethod.invoke(out, new Object[]{}); } catch (Exception e) { throw new IOException(e); } // Not in 0out.hflush(); } } @SuppressWarnings("unused") private void dumpHLog(Path log, FileSystem fs, Configuration conf) throws IOException { HLog.Entry entry; HLog.Reader in = HLog.getReader(fs, log, conf); while ((entry = in.next()) != null) { System.out.println(entry); } } private int countHLog(Path log, FileSystem fs, Configuration conf) throws IOException { int count = 0; HLog.Reader in = HLog.getReader(fs, log, conf); while (in.next() != null) { count++; } return count; } public long appendEntry(HLog.Writer writer, byte[] table, byte[] region, byte[] row, byte[] family, byte[] qualifier, byte[] value, long seq) throws IOException { LOG.info(Thread.currentThread().getName() + " append"); writer.append(createTestEntry(table, region, row, family, qualifier, value, seq)); LOG.info(Thread.currentThread().getName() + " sync"); writer.sync(); return seq; } private HLog.Entry createTestEntry( byte[] table, byte[] region, byte[] row, byte[] family, byte[] qualifier, byte[] value, long seq) { long time = System.nanoTime(); WALEdit edit = new WALEdit(); seq++; edit.add(new KeyValue(row, family, qualifier, time, KeyValue.Type.Put, value)); return new HLog.Entry(new HLogKey(region, table, seq, time, HConstants.DEFAULT_CLUSTER_ID), edit); } private void injectEmptyFile(String suffix, boolean closeFile) throws IOException { HLog.Writer writer = HLog.createWriter( fs, new Path(hlogDir, HLOG_FILE_PREFIX + suffix), conf); if (closeFile) writer.close(); } @SuppressWarnings("unused") private void listLogs(FileSystem fs, Path dir) throws IOException { for (FileStatus file : fs.listStatus(dir)) { System.out.println(file.getPath()); } } private int compareHLogSplitDirs(Path p1, Path p2) throws IOException { FileStatus[] f1 = fs.listStatus(p1); FileStatus[] f2 = fs.listStatus(p2); assertNotNull("Path " + p1 + " doesn't exist", f1); assertNotNull("Path " + p2 + " doesn't exist", f2); System.out.println("Files in " + p1 + ": " + Joiner.on(",").join(FileUtil.stat2Paths(f1))); System.out.println("Files in " + p2 + ": " + Joiner.on(",").join(FileUtil.stat2Paths(f2))); assertEquals(f1.length, f2.length); for (int i = 0; i < f1.length; i++) { // Regions now have a directory named RECOVERED_EDITS_DIR and in here // are split edit files. In below presume only 1. Path rd1 = HLog.getRegionDirRecoveredEditsDir(f1[i].getPath()); FileStatus[] rd1fs = fs.listStatus(rd1); assertEquals(1, rd1fs.length); Path rd2 = HLog.getRegionDirRecoveredEditsDir(f2[i].getPath()); FileStatus[] rd2fs = fs.listStatus(rd2); assertEquals(1, rd2fs.length); if (!logsAreEqual(rd1fs[0].getPath(), rd2fs[0].getPath())) { return -1; } } return 0; } private boolean logsAreEqual(Path p1, Path p2) throws IOException { HLog.Reader in1, in2; in1 = HLog.getReader(fs, p1, conf); in2 = HLog.getReader(fs, p2, conf); HLog.Entry entry1; HLog.Entry entry2; while ((entry1 = in1.next()) != null) { entry2 = in2.next(); if ((entry1.getKey().compareTo(entry2.getKey()) != 0) || (!entry1.getEdit().toString().equals(entry2.getEdit().toString()))) { return false; } } return true; } @org.junit.Rule public org.apache.hadoop.hbase.ResourceCheckerJUnitRule cu = new org.apache.hadoop.hbase.ResourceCheckerJUnitRule(); }