Java tutorial
/** * 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.hdfs.server.namenode; import java.io.*; import java.net.InetSocketAddress; import java.util.ArrayList; import java.util.Collection; import java.util.Iterator; import java.util.List; import java.util.concurrent.CountDownLatch; import java.util.concurrent.atomic.AtomicReference; import junit.framework.TestCase; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; import org.apache.hadoop.conf.Configuration; import org.apache.hadoop.fs.FileSystem; import org.apache.hadoop.fs.permission.*; import org.apache.hadoop.hdfs.MiniDFSCluster; import org.apache.hadoop.hdfs.protocol.FSConstants.SafeModeAction; import org.apache.hadoop.hdfs.server.common.Storage.StorageDirectory; import org.apache.hadoop.hdfs.server.namenode.FSImage.NameNodeDirType; import org.apache.hadoop.hdfs.server.namenode.FSImage.NameNodeFile; import org.apache.hadoop.hdfs.server.namenode.metrics.NameNodeMetrics; import org.mockito.Mockito; import org.mockito.invocation.InvocationOnMock; import org.mockito.stubbing.Answer; import static org.mockito.Mockito.*; /** * This class tests various synchronization bugs in FSEditLog rolling * and namespace saving. */ public class TestEditLogRace extends TestCase { private static final Log LOG = LogFactory.getLog(TestEditLogRace.class); // This test creates NUM_THREADS threads and each thread continuously writes // transactions static final int NUM_THREADS = 16; /** * The number of times to roll the edit log during the test. Since this * tests for a race condition, higher numbers are more likely to find * a bug if it exists, but the test will take longer. */ static final int NUM_ROLLS = 30; /** * The number of times to save the fsimage and create an empty edit log. */ static final int NUM_SAVE_IMAGE = 30; private List<Transactions> workers = new ArrayList<Transactions>(); private static final int NUM_DATA_NODES = 1; /** * Several of the test cases work by introducing a sleep * into an operation that is usually fast, and then verifying * that another operation blocks for at least this amount of time. * This value needs to be significantly longer than the average * time for an fsync() or enterSafeMode(). */ private static final int BLOCK_TIME = 10; // // an object that does a bunch of transactions // static class Transactions implements Runnable { final FSNamesystem namesystem; short replication = 3; long blockSize = 64; volatile boolean stopped = false; volatile Thread thr; final AtomicReference<Throwable> caught; Transactions(FSNamesystem ns, AtomicReference<Throwable> caught) { this.namesystem = ns; this.caught = caught; } // add a bunch of transactions. public void run() { thr = Thread.currentThread(); PermissionStatus p = FSNamesystem.getFSNamesystem() .createFsOwnerPermissions(new FsPermission((short) 0777)); int i = 0; while (!stopped) { try { String dirname = "/thr-" + thr.getId() + "-dir-" + i; namesystem.mkdirs(dirname, p); namesystem.delete(dirname, true); } catch (SafeModeException sme) { // This is OK - the tests will bring NN in and out of safemode } catch (Throwable e) { LOG.warn("Got error in transaction thread", e); caught.compareAndSet(null, e); break; } } } public void stop() { stopped = true; } public Thread getThread() { return thr; } } private void startTransactionWorkers(FSNamesystem namesystem, AtomicReference<Throwable> caughtErr) { // Create threads and make them run transactions concurrently. for (int i = 0; i < NUM_THREADS; i++) { Transactions trans = new Transactions(namesystem, caughtErr); new Thread(trans, "TransactionThread-" + i).start(); workers.add(trans); } } private void stopTransactionWorkers() { // wait for all transactions to get over for (Transactions worker : workers) { worker.stop(); } for (Transactions worker : workers) { Thread thr = worker.getThread(); try { if (thr != null) thr.join(); } catch (InterruptedException ie) { } } } /** * Tests rolling edit logs while transactions are ongoing. */ public void testEditLogRolling() throws Exception { // start a cluster Configuration conf = getConf(); MiniDFSCluster cluster = null; FileSystem fileSys = null; AtomicReference<Throwable> caughtErr = new AtomicReference<Throwable>(); try { cluster = new MiniDFSCluster(conf, NUM_DATA_NODES, true, null); cluster.waitActive(); fileSys = cluster.getFileSystem(); final FSNamesystem namesystem = cluster.getNameNode().namesystem; FSImage fsimage = namesystem.getFSImage(); FSEditLog editLog = fsimage.getEditLog(); // set small size of flush buffer FSEditLog.setBufferCapacity(2048); editLog.close(); editLog.open(); startTransactionWorkers(namesystem, caughtErr); for (int i = 0; i < NUM_ROLLS && caughtErr.get() == null; i++) { try { Thread.sleep(20); } catch (InterruptedException e) { } LOG.info("Starting roll " + i + "."); editLog.rollEditLog(); LOG.info("Roll complete " + i + "."); verifyEditLogs(fsimage); LOG.info("Starting purge " + i + "."); editLog.purgeEditLog(); LOG.info("Complete purge " + i + "."); } } finally { stopTransactionWorkers(); if (caughtErr.get() != null) { throw new RuntimeException(caughtErr.get()); } if (fileSys != null) fileSys.close(); if (cluster != null) cluster.shutdown(); } } private void verifyEditLogs(FSImage fsimage) throws IOException { // Verify that we can read in all the transactions that we have written. // If there were any corruptions, it is likely that the reading in // of these transactions will throw an exception. for (Iterator<StorageDirectory> it = fsimage.dirIterator(NameNodeDirType.EDITS); it.hasNext();) { File editFile = FSImage.getImageFile(it.next(), NameNodeFile.EDITS); System.out.println("Verifying file: " + editFile); int numEdits = FSEditLog.loadFSEdits(new FSEditLog.EditLogFileInputStream(editFile)); System.out.println("Number of edits: " + numEdits); } } /** * Tests saving fs image while transactions are ongoing. */ public void testSaveNamespace() throws Exception { // start a cluster Configuration conf = getConf(); MiniDFSCluster cluster = null; FileSystem fileSys = null; AtomicReference<Throwable> caughtErr = new AtomicReference<Throwable>(); try { cluster = new MiniDFSCluster(conf, NUM_DATA_NODES, true, null); cluster.waitActive(); fileSys = cluster.getFileSystem(); final FSNamesystem namesystem = FSNamesystem.getFSNamesystem(); FSImage fsimage = namesystem.getFSImage(); FSEditLog editLog = fsimage.getEditLog(); // set small size of flush buffer FSEditLog.setBufferCapacity(2048); editLog.close(); editLog.open(); assertTrue(editLog.getEditStreams().size() > 0); startTransactionWorkers(namesystem, caughtErr); for (int i = 0; i < NUM_SAVE_IMAGE; i++) { try { Thread.sleep(20); } catch (InterruptedException e) { } LOG.info("Save " + i + ": entering safe mode"); namesystem.enterSafeMode(); // Verify edit logs before the save verifyEditLogs(fsimage); LOG.info("Save " + i + ": saving namespace"); namesystem.saveNamespace(); LOG.info("Save " + i + ": leaving safemode"); // Verify that edit logs post save are also not corrupt verifyEditLogs(fsimage); namesystem.leaveSafeMode(false); LOG.info("Save " + i + ": complete"); } } finally { stopTransactionWorkers(); if (caughtErr.get() != null) { throw new RuntimeException(caughtErr.get()); } if (fileSys != null) fileSys.close(); if (cluster != null) cluster.shutdown(); } } private Configuration getConf() { Configuration conf = new Configuration(); conf.set("dfs.name.dir", MiniDFSCluster.getBaseDir() + "/data"); conf.setBoolean("dfs.permissions", false); return conf; } /** * The logSync() method in FSEditLog is unsynchronized whiel syncing * so that other threads can concurrently enqueue edits while the prior * sync is ongoing. This test checks that the log is saved correctly * if the saveImage occurs while the syncing thread is in the unsynchronized middle section. * * This replicates the following manual test proposed by Konstantin: * I start the name-node in debugger. * I do -mkdir and stop the debugger in logSync() just before it does flush. * Then I enter safe mode with another client * I start saveNamepsace and stop the debugger in * FSImage.saveFSImage() -> FSEditLog.createEditLogFile() * -> EditLogFileOutputStream.create() -> * after truncating the file but before writing LAYOUT_VERSION into it. * Then I let logSync() run. * Then I terminate the name-node. * After that the name-node wont start, since the edits file is broken. */ public void testSaveImageWhileSyncInProgress() throws Throwable { Configuration conf = getConf(); NameNode.format(conf); NameNode fakeNN = mock(NameNode.class); NameNode.myMetrics = new NameNodeMetrics(conf, fakeNN); Mockito.doReturn(new InetSocketAddress("127.0.0.1", 12345)).when(fakeNN).getNameNodeAddress(); final FSNamesystem namesystem = new FSNamesystem(fakeNN, conf); try { FSImage fsimage = namesystem.getFSImage(); FSEditLog editLog = fsimage.getEditLog(); ArrayList<EditLogOutputStream> streams = editLog.getEditStreams(); EditLogOutputStream spyElos = spy(streams.get(0)); streams.set(0, spyElos); final AtomicReference<Throwable> deferredException = new AtomicReference<Throwable>(); final CountDownLatch waitToEnterFlush = new CountDownLatch(1); final Thread doAnEditThread = new Thread() { public void run() { try { LOG.info("Starting mkdirs"); namesystem.mkdirs("/test", new PermissionStatus("test", "test", new FsPermission((short) 00755))); LOG.info("mkdirs complete"); } catch (Throwable ioe) { deferredException.set(ioe); waitToEnterFlush.countDown(); } } }; Answer<Void> blockingFlush = new Answer<Void>() { @Override public Void answer(InvocationOnMock invocation) throws Throwable { LOG.info("Flush called"); if (Thread.currentThread() == doAnEditThread) { LOG.info("edit thread: Telling main thread we made it to flush section..."); // Signal to main thread that the edit thread is in the racy section waitToEnterFlush.countDown(); LOG.info("edit thread: sleeping for " + BLOCK_TIME + "secs"); Thread.sleep(BLOCK_TIME * 1000); LOG.info("Going through to flush. This will allow the main thread to continue."); } invocation.callRealMethod(); LOG.info("Flush complete"); return null; } }; doAnswer(blockingFlush).when(spyElos).flush(); doAnEditThread.start(); // Wait for the edit thread to get to the logsync unsynchronized section LOG.info("Main thread: waiting to enter flush..."); waitToEnterFlush.await(); if (deferredException.get() != null) { throw deferredException.get(); } LOG.info("Main thread: detected that logSync is in unsynchronized section."); LOG.info("Trying to enter safe mode."); LOG.info("This should block for " + BLOCK_TIME + "sec, since flush will sleep that long"); long st = System.currentTimeMillis(); namesystem.setSafeMode(SafeModeAction.SAFEMODE_ENTER); long et = System.currentTimeMillis(); LOG.info("Entered safe mode"); // Make sure we really waited for the flush to complete! assertTrue(et - st > (BLOCK_TIME - 1) * 1000); // Once we're in safe mode, save namespace. namesystem.saveNamespace(); LOG.info("Joining on edit thread..."); doAnEditThread.join(); assertNull(deferredException.get()); verifyEditLogs(fsimage); } finally { LOG.info("Closing namesystem"); if (namesystem != null) namesystem.close(); } } /** * Most of the FSNamesystem methods have a synchronized section where they * update the name system itself and write to the edit log, and then * unsynchronized, they call logSync. This test verifies that, if an * operation has written to the edit log but not yet synced it, * we wait for that sync before entering safe mode. */ public void testSaveRightBeforeSync() throws Exception { Configuration conf = getConf(); NameNode.format(conf); NameNode fakeNN = mock(NameNode.class); NameNode.myMetrics = new NameNodeMetrics(conf, fakeNN); Mockito.doReturn(new InetSocketAddress("127.0.0.1", 12345)).when(fakeNN).getNameNodeAddress(); final FSNamesystem namesystem = new FSNamesystem(fakeNN, conf); try { FSImage fsimage = namesystem.getFSImage(); FSEditLog editLog = spy(fsimage.getEditLog()); fsimage.editLog = editLog; final AtomicReference<Throwable> deferredException = new AtomicReference<Throwable>(); final CountDownLatch waitToEnterSync = new CountDownLatch(1); final Thread doAnEditThread = new Thread() { public void run() { try { LOG.info("Starting mkdirs"); namesystem.mkdirs("/test", new PermissionStatus("test", "test", new FsPermission((short) 00755))); LOG.info("mkdirs complete"); } catch (Throwable ioe) { deferredException.set(ioe); waitToEnterSync.countDown(); } } }; Answer<Void> blockingSync = new Answer<Void>() { @Override public Void answer(InvocationOnMock invocation) throws Throwable { LOG.info("logSync called"); if (Thread.currentThread() == doAnEditThread) { LOG.info("edit thread: Telling main thread we made it just before logSync..."); waitToEnterSync.countDown(); LOG.info("edit thread: sleeping for " + BLOCK_TIME + "secs"); Thread.sleep(BLOCK_TIME * 1000); LOG.info("Going through to logSync. This will allow the main thread to continue."); } invocation.callRealMethod(); LOG.info("logSync complete"); return null; } }; doAnswer(blockingSync).when(editLog).logSync(); doAnEditThread.start(); LOG.info("Main thread: waiting to just before logSync..."); waitToEnterSync.await(); assertNull(deferredException.get()); LOG.info("Main thread: detected that logSync about to be called."); LOG.info("Trying to enter safe mode."); LOG.info("This should block for " + BLOCK_TIME + "sec, since we have pending edits"); long st = System.currentTimeMillis(); namesystem.setSafeMode(SafeModeAction.SAFEMODE_ENTER); long et = System.currentTimeMillis(); LOG.info("Entered safe mode"); // Make sure we really waited for the flush to complete! assertTrue(et - st > (BLOCK_TIME - 1) * 1000); // Once we're in safe mode, save namespace. namesystem.saveNamespace(); LOG.info("Joining on edit thread..."); doAnEditThread.join(); assertNull(deferredException.get()); verifyEditLogs(fsimage); } finally { LOG.info("Closing namesystem"); if (namesystem != null) namesystem.close(); } } }