Examples with LogCapturer org.apache.hadoop.test.GenericTestUtils.LogCapturer used on opensource projects

Example 11 with LogCapturer

use of org.apache.hadoop.test.GenericTestUtils.LogCapturer in project hadoop by apache.

the class TestCheckpoint method testStorageAlreadyLockedErrorMessage.

/**
   * Test that, an attempt to lock a storage that is already locked by nodename,
   * logs error message that includes JVM name of the namenode that locked it.
   */
@Test
public void testStorageAlreadyLockedErrorMessage() throws Exception {
    Configuration conf = new HdfsConfiguration();
    MiniDFSCluster cluster = null;
    StorageDirectory savedSd = null;
    try {
        cluster = new MiniDFSCluster.Builder(conf).numDataNodes(0).build();
        NNStorage storage = cluster.getNameNode().getFSImage().getStorage();
        for (StorageDirectory sd : storage.dirIterable(null)) {
            assertLockFails(sd);
            savedSd = sd;
        }
        LogCapturer logs = GenericTestUtils.LogCapturer.captureLogs(LogFactory.getLog(Storage.class));
        try {
            // try to lock the storage that's already locked
            savedSd.lock();
            fail("Namenode should not be able to lock a storage" + " that is already locked");
        } catch (IOException ioe) {
            // cannot read lock file on Windows, so message cannot get JVM name
            String lockingJvmName = Path.WINDOWS ? "" : " " + ManagementFactory.getRuntimeMXBean().getName();
            String expectedLogMessage = "It appears that another node " + lockingJvmName + " has already locked the storage directory";
            assertTrue("Log output does not contain expected log message: " + expectedLogMessage, logs.getOutput().contains(expectedLogMessage));
        }
    } finally {
        cleanup(cluster);
        cluster = null;
    }
}

Example 12 with LogCapturer

use of org.apache.hadoop.test.GenericTestUtils.LogCapturer in project hadoop by apache.

the class TestAuditLogger method testAuditLoggerWithCallContext.

/**
   * Verify that the audit logger is aware of the call context
   */
@Test
public void testAuditLoggerWithCallContext() throws IOException {
    Configuration conf = new HdfsConfiguration();
    conf.setBoolean(HADOOP_CALLER_CONTEXT_ENABLED_KEY, true);
    conf.setInt(HADOOP_CALLER_CONTEXT_MAX_SIZE_KEY, 128);
    conf.setInt(HADOOP_CALLER_CONTEXT_SIGNATURE_MAX_SIZE_KEY, 40);
    MiniDFSCluster cluster = new MiniDFSCluster.Builder(conf).build();
    LogCapturer auditlog = LogCapturer.captureLogs(FSNamesystem.auditLog);
    try {
        cluster.waitClusterUp();
        final FileSystem fs = cluster.getFileSystem();
        final long time = System.currentTimeMillis();
        final Path p = new Path("/");
        assertNull(CallerContext.getCurrent());
        // context-only
        CallerContext context = new CallerContext.Builder("setTimes").build();
        CallerContext.setCurrent(context);
        LOG.info("Set current caller context as {}", CallerContext.getCurrent());
        fs.setTimes(p, time, time);
        assertTrue(auditlog.getOutput().endsWith(String.format("callerContext=setTimes%n")));
        auditlog.clearOutput();
        // context with signature
        context = new CallerContext.Builder("setTimes").setSignature("L".getBytes(CallerContext.SIGNATURE_ENCODING)).build();
        CallerContext.setCurrent(context);
        LOG.info("Set current caller context as {}", CallerContext.getCurrent());
        fs.setTimes(p, time, time);
        assertTrue(auditlog.getOutput().endsWith(String.format("callerContext=setTimes:L%n")));
        auditlog.clearOutput();
        // long context is truncated
        final String longContext = StringUtils.repeat("foo", 100);
        context = new CallerContext.Builder(longContext).setSignature("L".getBytes(CallerContext.SIGNATURE_ENCODING)).build();
        CallerContext.setCurrent(context);
        LOG.info("Set current caller context as {}", CallerContext.getCurrent());
        fs.setTimes(p, time, time);
        assertTrue(auditlog.getOutput().endsWith(String.format("callerContext=%s:L%n", longContext.substring(0, 128))));
        auditlog.clearOutput();
        // empty context is ignored
        context = new CallerContext.Builder("").setSignature("L".getBytes(CallerContext.SIGNATURE_ENCODING)).build();
        CallerContext.setCurrent(context);
        LOG.info("Set empty caller context");
        fs.setTimes(p, time, time);
        assertFalse(auditlog.getOutput().contains("callerContext="));
        auditlog.clearOutput();
        // caller context is inherited in child thread
        context = new CallerContext.Builder("setTimes").setSignature("L".getBytes(CallerContext.SIGNATURE_ENCODING)).build();
        CallerContext.setCurrent(context);
        LOG.info("Set current caller context as {}", CallerContext.getCurrent());
        Thread child = new Thread(new Runnable() {

            @Override
            public void run() {
                try {
                    fs.setTimes(p, time, time);
                } catch (IOException e) {
                    fail("Unexpected exception found." + e);
                }
            }
        });
        child.start();
        try {
            child.join();
        } catch (InterruptedException ignored) {
        // Ignore
        }
        assertTrue(auditlog.getOutput().endsWith(String.format("callerContext=setTimes:L%n")));
        auditlog.clearOutput();
        // caller context is overridden in child thread
        final CallerContext childContext = new CallerContext.Builder("setPermission").setSignature("L".getBytes(CallerContext.SIGNATURE_ENCODING)).build();
        LOG.info("Set current caller context as {}", CallerContext.getCurrent());
        child = new Thread(new Runnable() {

            @Override
            public void run() {
                try {
                    CallerContext.setCurrent(childContext);
                    fs.setPermission(p, new FsPermission((short) 777));
                } catch (IOException e) {
                    fail("Unexpected exception found." + e);
                }
            }
        });
        child.start();
        try {
            child.join();
        } catch (InterruptedException ignored) {
        // Ignore
        }
        assertTrue(auditlog.getOutput().endsWith(String.format("callerContext=setPermission:L%n")));
        auditlog.clearOutput();
        // reuse the current context's signature
        context = new CallerContext.Builder("mkdirs").setSignature(CallerContext.getCurrent().getSignature()).build();
        CallerContext.setCurrent(context);
        LOG.info("Set current caller context as {}", CallerContext.getCurrent());
        fs.mkdirs(new Path("/reuse-context-signature"));
        assertTrue(auditlog.getOutput().endsWith(String.format("callerContext=mkdirs:L%n")));
        auditlog.clearOutput();
        // too long signature is ignored
        context = new CallerContext.Builder("setTimes").setSignature(new byte[41]).build();
        CallerContext.setCurrent(context);
        LOG.info("Set current caller context as {}", CallerContext.getCurrent());
        fs.setTimes(p, time, time);
        assertTrue(auditlog.getOutput().endsWith(String.format("callerContext=setTimes%n")));
        auditlog.clearOutput();
        // null signature is ignored
        context = new CallerContext.Builder("setTimes").setSignature(null).build();
        CallerContext.setCurrent(context);
        LOG.info("Set current caller context as {}", CallerContext.getCurrent());
        fs.setTimes(p, time, time);
        assertTrue(auditlog.getOutput().endsWith(String.format("callerContext=setTimes%n")));
        auditlog.clearOutput();
        // empty signature is ignored
        context = new CallerContext.Builder("mkdirs").setSignature("".getBytes(CallerContext.SIGNATURE_ENCODING)).build();
        CallerContext.setCurrent(context);
        LOG.info("Set current caller context as {}", CallerContext.getCurrent());
        fs.mkdirs(new Path("/empty-signature"));
        assertTrue(auditlog.getOutput().endsWith(String.format("callerContext=mkdirs%n")));
        auditlog.clearOutput();
        // invalid context is not passed to the rpc
        context = new CallerContext.Builder(null).build();
        CallerContext.setCurrent(context);
        LOG.info("Set current caller context as {}", CallerContext.getCurrent());
        fs.mkdirs(new Path("/empty-signature"));
        assertFalse(auditlog.getOutput().contains("callerContext="));
        auditlog.clearOutput();
    } finally {
        cluster.shutdown();
    }
}

Example 13 with LogCapturer

use of org.apache.hadoop.test.GenericTestUtils.LogCapturer in project hadoop by apache.

the class TestFSNamesystemLock method testFSReadLockLongHoldingReport.

/**
   * Test when FSNamesystem read lock is held for a long time,
   * logger will report it.
   */
@Test(timeout = 45000)
public void testFSReadLockLongHoldingReport() throws Exception {
    final long readLockReportingThreshold = 100L;
    final long readLockSuppressWarningInterval = 10000L;
    final String readLockLogStmt = "FSNamesystem read lock held for ";
    Configuration conf = new Configuration();
    conf.setLong(DFSConfigKeys.DFS_NAMENODE_READ_LOCK_REPORTING_THRESHOLD_MS_KEY, readLockReportingThreshold);
    conf.setTimeDuration(DFSConfigKeys.DFS_LOCK_SUPPRESS_WARNING_INTERVAL_KEY, readLockSuppressWarningInterval, TimeUnit.MILLISECONDS);
    final FakeTimer timer = new FakeTimer();
    final FSNamesystemLock fsnLock = new FSNamesystemLock(conf, null, timer);
    timer.advance(readLockSuppressWarningInterval);
    LogCapturer logs = LogCapturer.captureLogs(FSNamesystem.LOG);
    GenericTestUtils.setLogLevel(FSNamesystem.LOG, Level.INFO);
    // Don't report if the read lock is held for a short time
    fsnLock.readLock();
    fsnLock.readUnlock();
    assertFalse(logs.getOutput().contains(GenericTestUtils.getMethodName()) && logs.getOutput().contains(readLockLogStmt));
    // Report the first read lock warning if it is held for a long time
    fsnLock.readLock();
    timer.advance(readLockReportingThreshold + 10);
    logs.clearOutput();
    fsnLock.readUnlock();
    assertTrue(logs.getOutput().contains(GenericTestUtils.getMethodName()) && logs.getOutput().contains(readLockLogStmt));
    // Track but do not Report if the write lock is held for a long time but
    // time since last report does not exceed the suppress warning interval
    fsnLock.readLock();
    timer.advance(readLockReportingThreshold + 10);
    logs.clearOutput();
    fsnLock.readUnlock();
    assertFalse(logs.getOutput().contains(GenericTestUtils.getMethodName()) && logs.getOutput().contains(readLockLogStmt));
    // Track but do not Report if it's held for a long time when re-entering
    // read lock but time since last report does not exceed the suppress
    // warning interval
    fsnLock.readLock();
    timer.advance(readLockReportingThreshold / 2 + 1);
    fsnLock.readLock();
    timer.advance(readLockReportingThreshold / 2 + 1);
    logs.clearOutput();
    fsnLock.readUnlock();
    assertFalse(logs.getOutput().contains(GenericTestUtils.getMethodName()) || logs.getOutput().contains(readLockLogStmt));
    logs.clearOutput();
    fsnLock.readUnlock();
    assertFalse(logs.getOutput().contains(GenericTestUtils.getMethodName()) && logs.getOutput().contains(readLockLogStmt));
    // Report if it's held for a long time (and time since last report
    // exceeds the suppress warning interval) while another thread also has the
    // read lock. Let one thread hold the lock long enough to activate an
    // alert, then have another thread grab the read lock to ensure that this
    // doesn't reset the timing.
    timer.advance(readLockSuppressWarningInterval);
    logs.clearOutput();
    final CountDownLatch barrier = new CountDownLatch(1);
    final CountDownLatch barrier2 = new CountDownLatch(1);
    Thread t1 = new Thread() {

        @Override
        public void run() {
            try {
                fsnLock.readLock();
                timer.advance(readLockReportingThreshold + 1);
                // Allow for t2 to acquire the read lock
                barrier.countDown();
                // Wait until t2 has the read lock
                barrier2.await();
                fsnLock.readUnlock();
            } catch (InterruptedException e) {
                fail("Interrupted during testing");
            }
        }
    };
    Thread t2 = new Thread() {

        @Override
        public void run() {
            try {
                // Wait until t1 finishes sleeping
                barrier.await();
                fsnLock.readLock();
                // Allow for t1 to unlock
                barrier2.countDown();
                fsnLock.readUnlock();
            } catch (InterruptedException e) {
                fail("Interrupted during testing");
            }
        }
    };
    t1.start();
    t2.start();
    t1.join();
    t2.join();
    // Look for the differentiating class names in the stack trace
    String stackTracePatternString = String.format("INFO.+%s(.+\n){5}\\Q%%s\\E\\.run", readLockLogStmt);
    Pattern t1Pattern = Pattern.compile(String.format(stackTracePatternString, t1.getClass().getName()));
    assertTrue(t1Pattern.matcher(logs.getOutput()).find());
    Pattern t2Pattern = Pattern.compile(String.format(stackTracePatternString, t2.getClass().getName()));
    assertFalse(t2Pattern.matcher(logs.getOutput()).find());
    assertTrue(logs.getOutput().contains("Number of suppressed read-lock reports: 2"));
}

Example 14 with LogCapturer

use of org.apache.hadoop.test.GenericTestUtils.LogCapturer in project hadoop by apache.

the class TestNativeAzureFileSystemClientLogging method testLoggingDisabled.

@Test
public void testLoggingDisabled() throws Exception {
    LogCapturer logs = LogCapturer.captureLogs(new Log4JLogger(Logger.getRootLogger()));
    // Update configuration based on the Test.
    updateFileSystemConfiguration(false);
    performWASBOperations();
    assertFalse(verifyStorageClientLogs(logs.getOutput(), TEMP_DIR));
}