/**
* 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.mapred;
import java.io.DataOutputStream;
import java.io.File;
import java.io.FileOutputStream;
import java.io.IOException;
import java.net.URI;
import java.util.Arrays;
import java.util.HashMap;
import java.util.Map;
import java.util.Random;
import org.apache.commons.logging.LogFactory;
import org.apache.commons.logging.Log;
import org.apache.hadoop.conf.Configuration;
import org.apache.hadoop.filecache.DistributedCache;
import org.apache.hadoop.fs.FileSystem;
import org.apache.hadoop.fs.FileUtil;
import org.apache.hadoop.fs.Path;
import org.apache.hadoop.io.LongWritable;
import org.apache.hadoop.io.Text;
import org.apache.hadoop.mapred.TaskLog.LogFileDetail;
import org.apache.hadoop.mapred.TaskLog.LogName;
import org.apache.hadoop.mapred.lib.IdentityMapper;
import org.apache.hadoop.mapreduce.server.tasktracker.JVMInfo;
import org.apache.hadoop.mapreduce.server.tasktracker.userlogs.JvmFinishedEvent;
import org.apache.hadoop.mapreduce.server.tasktracker.userlogs.UserLogManager;
import org.apache.hadoop.mapreduce.split.JobSplit;
import org.junit.After;
import org.junit.Ignore;
import org.junit.Test;
import static org.junit.Assert.*;
/**
* Verify the logs' truncation functionality.
*/
public class TestTaskLogsTruncater {
static final Log LOG = LogFactory.getLog(TestTaskLogsTruncater.class);
private static int truncatedMsgSize = TaskLogsTruncater.TRUNCATED_MSG.getBytes().length;
/**
* clean-up any stale directories after enabling writable permissions for all
* attempt-dirs.
*
* @throws IOException
*/
@After
public void tearDown() throws IOException {
File logDir = TaskLog.getUserLogDir();
for (File attemptDir : logDir.listFiles()) {
attemptDir.setWritable(true);
FileUtil.fullyDelete(attemptDir);
}
}
private void writeBytes(TaskAttemptID firstAttemptID, TaskAttemptID attemptID,
LogName logName, long numBytes, boolean random, char data) throws IOException {
File logFile = TaskLog.getTaskLogFile(firstAttemptID, false, logName);
File logLocation = logFile.getParentFile();
LOG.info("Going to write " + numBytes + " real bytes to the log file "
+ logFile);
if (!logLocation.exists()
&& !logLocation.mkdirs()) {
throw new IOException("Couldn't create all ancestor dirs for "
+ logFile);
}
File attemptDir = TaskLog.getAttemptDir(attemptID, false);
if (!attemptDir.exists() && !attemptDir.mkdirs()) {
throw new IOException("Couldn't create all ancestor dirs for "
+ logFile);
}
// Need to call up front to set currenttaskid.
TaskLog.syncLogs(logLocation.toString(), attemptID, false, true);
FileOutputStream outputStream = new FileOutputStream(logFile, true);
Random r = new Random();
for (long i = 0; i < numBytes; i++) {
if(random) {
outputStream.write(r.nextInt());
} else {
outputStream.write(data);
}
}
outputStream.close();
TaskLog.syncLogs(logLocation.toString(), attemptID, false, true);
LOG.info("Written " + logFile.length() + " real bytes to the log file "
+ logFile);
}
private void writeRandomBytes(TaskAttemptID firstAttemptID,
TaskAttemptID attemptID, LogName logName, long numBytes)
throws IOException {
writeBytes(firstAttemptID, attemptID, logName, numBytes, true, ' ');
}
private void writeRealChars(TaskAttemptID firstAttemptID,
TaskAttemptID attemptID, LogName logName, long numChars, char data)
throws IOException {
writeBytes(firstAttemptID, attemptID, logName, numChars, false, data);
}
private static Map<LogName, Long> getAllLogsFileLengths(
TaskAttemptID tid, boolean isCleanup) throws IOException {
Map<LogName, Long> allLogsFileLengths = new HashMap<LogName, Long>();
// If the index file doesn't exist, we cannot get log-file lengths. So set
// them to zero.
if (!TaskLog.getIndexFile(tid, isCleanup).exists()) {
for (LogName log : LogName.values()) {
allLogsFileLengths.put(log, Long.valueOf(0));
}
return allLogsFileLengths;
}
Map<LogName, LogFileDetail> logFilesDetails =
TaskLog.getAllLogsFileDetails(tid, isCleanup);
for (LogName log : logFilesDetails.keySet()) {
allLogsFileLengths.put(log,
Long.valueOf(logFilesDetails.get(log).length));
}
return allLogsFileLengths;
}
private Configuration setRetainSizes(long mapRetainSize,
long reduceRetainSize) {
Configuration conf = new Configuration();
conf.setLong(TaskLogsTruncater.MAP_USERLOG_RETAIN_SIZE, mapRetainSize);
conf.setLong(TaskLogsTruncater.REDUCE_USERLOG_RETAIN_SIZE, reduceRetainSize);
return conf;
}
/**
* Test cases which don't need any truncation of log-files. Without JVM-reuse.
*
* @throws IOException
*/
@Test
public void testNoTruncationNeeded() throws IOException {
Configuration conf = setRetainSizes(1000L, 1000L);
TaskLogsTruncater trunc = new TaskLogsTruncater(conf);
TaskID baseId = new TaskID();
int taskcount = 0;
TaskAttemptID attemptID = new TaskAttemptID(baseId, taskcount++);
Task task = new MapTask(null, attemptID, 0, new JobSplit.TaskSplitIndex(),
0);
// Let the tasks write logs within retain-size
for (LogName log : LogName.values()) {
writeRandomBytes(attemptID, attemptID, log, 500);
}
File logIndex = TaskLog.getIndexFile(attemptID, false);
long indexModificationTimeStamp = logIndex.lastModified();
File attemptDir = TaskLog.getAttemptDir(attemptID, false);
assertTrue(attemptDir + " doesn't exist!", attemptDir.exists());
assertEquals("index file got modified", indexModificationTimeStamp,
logIndex.lastModified());
// Finish the task and the JVM too.
JVMInfo jvmInfo = new JVMInfo(attemptDir, Arrays.asList(task));
trunc.truncateLogs(jvmInfo);
// There should be no truncation of the log-file.
assertTrue(attemptDir.exists());
assertEquals("index file got modified", indexModificationTimeStamp,
logIndex.lastModified());
Map<LogName, Long> logLengths = getAllLogsFileLengths(attemptID, false);
for (LogName log : LogName.values()) {
File logFile = TaskLog.getTaskLogFile(attemptID, false, log);
assertEquals(500, logFile.length());
// The index file should also be proper.
assertEquals(500, logLengths.get(log).longValue());
}
// truncate it once again
trunc.truncateLogs(jvmInfo);
assertEquals("index file got modified", indexModificationTimeStamp,
logIndex.lastModified());
logLengths = getAllLogsFileLengths(attemptID, false);
for (LogName log : LogName.values()) {
File logFile = TaskLog.getTaskLogFile(attemptID, false, log);
assertEquals(500, logFile.length());
// The index file should also be proper.
assertEquals(500, logLengths.get(log).longValue());
}
}
/**
* Test the disabling of truncation of log-file.
*
* @throws IOException
*/
@Test
public void testDisabledLogTruncation() throws IOException {
// Anything less than 0 disables the truncation.
Configuration conf = setRetainSizes(-1L, -1L);
TaskLogsTruncater trunc = new TaskLogsTruncater(conf);
TaskID baseId = new TaskID();
int taskcount = 0;
TaskAttemptID attemptID = new TaskAttemptID(baseId, taskcount++);
Task task = new MapTask(null, attemptID, 0, new JobSplit.TaskSplitIndex(),
0);
// Let the tasks write some logs
for (LogName log : LogName.values()) {
writeRandomBytes(attemptID, attemptID, log, 1500);
}
File attemptDir = TaskLog.getAttemptDir(attemptID, false);
assertTrue(attemptDir + " doesn't exist!", attemptDir.exists());
// Finish the task and the JVM too.
JVMInfo jvmInfo = new JVMInfo(attemptDir, Arrays.asList(task));
trunc.truncateLogs(jvmInfo);
// The log-file should not be truncated.
assertTrue(attemptDir.exists());
Map<LogName, Long> logLengths = getAllLogsFileLengths(attemptID, false);
for (LogName log : LogName.values()) {
File logFile = TaskLog.getTaskLogFile(attemptID, false, log);
assertEquals(1500, logFile.length());
// The index file should also be proper.
assertEquals(1500, logLengths.get(log).longValue());
}
}
/**
* Test the truncation of log-file when JVMs are not reused.
*
* @throws IOException
*/
@Test
public void testLogTruncationOnFinishing() throws IOException {
Configuration conf = setRetainSizes(1000L, 1000L);
TaskLogsTruncater trunc = new TaskLogsTruncater(conf);
TaskID baseId = new TaskID();
int taskcount = 0;
TaskAttemptID attemptID = new TaskAttemptID(baseId, taskcount++);
Task task = new MapTask(null, attemptID, 0, new JobSplit.TaskSplitIndex(),
0);
// Let the tasks write logs more than retain-size
for (LogName log : LogName.values()) {
writeRandomBytes(attemptID, attemptID, log, 1500);
}
File attemptDir = TaskLog.getAttemptDir(attemptID, false);
assertTrue(attemptDir + " doesn't exist!", attemptDir.exists());
// Finish the task and the JVM too.
JVMInfo jvmInfo = new JVMInfo(attemptDir, Arrays.asList(task));
trunc.truncateLogs(jvmInfo);
// The log-file should now be truncated.
assertTrue(attemptDir.exists());
Map<LogName, Long> logLengths = getAllLogsFileLengths(attemptID, false);
for (LogName log : LogName.values()) {
File logFile = TaskLog.getTaskLogFile(attemptID, false, log);
assertEquals(1000 + truncatedMsgSize, logFile.length());
// The index file should also be proper.
assertEquals(1000 + truncatedMsgSize, logLengths.get(log).longValue());
}
// truncate once again
logLengths = getAllLogsFileLengths(attemptID, false);
for (LogName log : LogName.values()) {
File logFile = TaskLog.getTaskLogFile(attemptID, false, log);
assertEquals(1000 + truncatedMsgSize, logFile.length());
// The index file should also be proper.
assertEquals(1000 + truncatedMsgSize, logLengths.get(log).longValue());
}
}
/**
* Test the truncation of log-file.
*
* It writes two log files and truncates one, does not truncate other.
*
* @throws IOException
*/
@Test
public void testLogTruncation() throws IOException {
Configuration conf = setRetainSizes(1000L, 1000L);
TaskLogsTruncater trunc = new TaskLogsTruncater(conf);
TaskID baseId = new TaskID();
int taskcount = 0;
TaskAttemptID attemptID = new TaskAttemptID(baseId, taskcount++);
Task task = new MapTask(null, attemptID, 0, new JobSplit.TaskSplitIndex(),
0);
// Let the tasks write logs more than retain-size
writeRandomBytes(attemptID, attemptID, LogName.SYSLOG, 1500);
writeRandomBytes(attemptID, attemptID, LogName.STDERR, 500);
File attemptDir = TaskLog.getAttemptDir(attemptID, false);
assertTrue(attemptDir + " doesn't exist!", attemptDir.exists());
// Finish the task and the JVM too.
JVMInfo jvmInfo = new JVMInfo(attemptDir, Arrays.asList(task));
trunc.truncateLogs(jvmInfo);
// The log-file should now be truncated.
assertTrue(attemptDir.exists());
Map<LogName, Long> logLengths = getAllLogsFileLengths(attemptID, false);
File logFile = TaskLog.getTaskLogFile(attemptID, false, LogName.SYSLOG);
assertEquals(1000 + truncatedMsgSize, logFile.length());
// The index file should also be proper.
assertEquals(1000 + truncatedMsgSize, logLengths.get(LogName.SYSLOG)
.longValue());
String syslog = TestMiniMRMapRedDebugScript.readTaskLog(LogName.SYSLOG,
attemptID, false);
assertTrue(syslog.startsWith(TaskLogsTruncater.TRUNCATED_MSG));
logFile = TaskLog.getTaskLogFile(attemptID, false, LogName.STDERR);
assertEquals(500, logFile.length());
// The index file should also be proper.
assertEquals(500, logLengths.get(LogName.STDERR).longValue());
String stderr = TestMiniMRMapRedDebugScript.readTaskLog(LogName.STDERR,
attemptID, false);
assertFalse(stderr.startsWith(TaskLogsTruncater.TRUNCATED_MSG));
// truncate once again
trunc.truncateLogs(jvmInfo);
logLengths = getAllLogsFileLengths(attemptID, false);
logFile = TaskLog.getTaskLogFile(attemptID, false, LogName.SYSLOG);
assertEquals(1000 + truncatedMsgSize, logFile.length());
// The index file should also be proper.
assertEquals(1000 + truncatedMsgSize, logLengths.get(LogName.SYSLOG)
.longValue());
logFile = TaskLog.getTaskLogFile(attemptID, false, LogName.STDERR);
assertEquals(500, logFile.length());
// The index file should also be proper.
assertEquals(500, logLengths.get(LogName.STDERR).longValue());
}
/**
* Test the truncation of log-file when JVM-reuse is enabled.
*
* @throws IOException
*/
@Test
public void testLogTruncationOnFinishingWithJVMReuse() throws IOException {
Configuration conf = setRetainSizes(150L, 150L);
TaskLogsTruncater trunc = new TaskLogsTruncater(conf);
TaskID baseTaskID = new TaskID();
int attemptsCount = 0;
// Assuming the job's retain size is 150
TaskAttemptID attempt1 = new TaskAttemptID(baseTaskID, attemptsCount++);
Task task1 = new MapTask(null, attempt1, 0, new JobSplit.TaskSplitIndex(),
0);
// Let the tasks write logs more than retain-size
writeRealChars(attempt1, attempt1, LogName.SYSLOG, 200, 'A');
File attemptDir = TaskLog.getAttemptDir(attempt1, false);
assertTrue(attemptDir + " doesn't exist!", attemptDir.exists());
// Start another attempt in the same JVM
TaskAttemptID attempt2 = new TaskAttemptID(baseTaskID, attemptsCount++);
Task task2 = new MapTask(null, attempt2, 0, new JobSplit.TaskSplitIndex(),
0);
// Let attempt2 also write some logs
writeRealChars(attempt1, attempt2, LogName.SYSLOG, 100, 'B');
// Start yet another attempt in the same JVM
TaskAttemptID attempt3 = new TaskAttemptID(baseTaskID, attemptsCount++);
Task task3 = new MapTask(null, attempt3, 0, new JobSplit.TaskSplitIndex(),
0);
// Let attempt3 also write some logs
writeRealChars(attempt1, attempt3, LogName.SYSLOG, 225, 'C');
// Finish the JVM.
JVMInfo jvmInfo = new JVMInfo(attemptDir,
Arrays.asList((new Task[] { task1, task2, task3 })));
trunc.truncateLogs(jvmInfo);
// The log-file should now be truncated.
assertTrue(attemptDir.exists());
File logFile = TaskLog.getTaskLogFile(attempt1, false, LogName.SYSLOG);
assertEquals(400 + (2 * truncatedMsgSize), logFile.length());
// The index files should also be proper.
assertEquals(150 + truncatedMsgSize, getAllLogsFileLengths(attempt1, false)
.get(LogName.SYSLOG).longValue());
assertEquals(100, getAllLogsFileLengths(attempt2, false)
.get(LogName.SYSLOG).longValue());
assertEquals(150 + truncatedMsgSize, getAllLogsFileLengths(attempt3, false)
.get(LogName.SYSLOG).longValue());
// assert data for attempt1
String syslog = TestMiniMRMapRedDebugScript.readTaskLog(LogName.SYSLOG,
attempt1, false);
assertTrue(syslog.startsWith(TaskLogsTruncater.TRUNCATED_MSG));
String truncatedLog = syslog.substring(truncatedMsgSize);
for (int i = 0 ; i < 150; i++) {
assertEquals("Truncation didn't happen properly. At "
+ (i + 1) + "th byte, expected 'A' but found "
+ truncatedLog.charAt(i), 'A', truncatedLog.charAt(i));
}
// assert data for attempt2
syslog = TestMiniMRMapRedDebugScript.readTaskLog(LogName.SYSLOG,
attempt2, false);
for (int i = 0 ; i < 100; i++) {
assertEquals("Truncation didn't happen properly. At "
+ (i + 1) + "th byte, expected 'B' but found "
+ truncatedLog.charAt(i), 'B', syslog.charAt(i));
}
// assert data for attempt3
syslog = TestMiniMRMapRedDebugScript.readTaskLog(LogName.SYSLOG,
attempt3, false);
assertTrue(syslog.startsWith(TaskLogsTruncater.TRUNCATED_MSG));
truncatedLog = syslog.substring(truncatedMsgSize);
for (int i = 0 ; i < 150; i++) {
assertEquals("Truncation didn't happen properly. At "
+ (i + 1) + "th byte, expected 'C' but found "
+ truncatedLog.charAt(i), 'C', truncatedLog.charAt(i));
}
trunc.truncateLogs(jvmInfo);
// First and third attempts' logs are only truncated, so include 2*length of
// TRUNCATED_MSG header
assertEquals(400 + 2 * truncatedMsgSize, logFile.length());
}
private static String TEST_ROOT_DIR =
new File(System.getProperty("test.build.data", "/tmp")).toURI().toString().replace(
' ', '+');
private static String STDERR_LOG = "stderr log";
public static class LoggingMapper<K, V> extends IdentityMapper<K, V> {
public void map(K key, V val, OutputCollector<K, V> output,
Reporter reporter) throws IOException {
// Write lots of logs
for (int i = 0; i < 1000; i++) {
System.out.println("Lots of logs! Lots of logs! "
+ "Waiting to be truncated! Lots of logs!");
}
// write some log into stderr
System.err.println(STDERR_LOG);
super.map(key, val, output, reporter);
}
}
/**
* Test logs monitoring with {@link MiniMRCluster}
*
* @throws IOException
*/
@Test
@Ignore // Trunction is now done in the Child JVM, because the TaskTracker
// no longer has write access to the user log dir. MiniMRCluster
// needs to be modified to put the config params set here in a config
// on the Child's classpath
public void testLogsMonitoringWithMiniMR() throws IOException {
MiniMRCluster mr = null;
try {
final long LSIZE = 10000L;
JobConf clusterConf = new JobConf();
clusterConf.setLong(TaskLogsTruncater.MAP_USERLOG_RETAIN_SIZE, LSIZE);
clusterConf.setLong(TaskLogsTruncater.REDUCE_USERLOG_RETAIN_SIZE, LSIZE);
mr = new MiniMRCluster(1, "file:///", 3, null, null, clusterConf);
JobConf conf = mr.createJobConf();
Path inDir = new Path(TEST_ROOT_DIR + "/input");
Path outDir = new Path(TEST_ROOT_DIR + "/output");
FileSystem fs = FileSystem.get(conf);
if (fs.exists(outDir)) {
fs.delete(outDir, true);
}
if (!fs.exists(inDir)) {
fs.mkdirs(inDir);
}
String input = "The quick brown fox jumped over the lazy dog";
DataOutputStream file = fs.create(new Path(inDir, "part-0"));
file.writeBytes(input);
file.close();
conf.setInputFormat(TextInputFormat.class);
conf.setOutputKeyClass(LongWritable.class);
conf.setOutputValueClass(Text.class);
FileInputFormat.setInputPaths(conf, inDir);
FileOutputFormat.setOutputPath(conf, outDir);
conf.setNumMapTasks(1);
conf.setNumReduceTasks(0);
conf.setMapperClass(LoggingMapper.class);
RunningJob job = JobClient.runJob(conf);
assertTrue(job.getJobState() == JobStatus.SUCCEEDED);
for (TaskCompletionEvent tce : job.getTaskCompletionEvents(0)) {
long length =
TaskLog.getTaskLogFile(tce.getTaskAttemptId(), false,
TaskLog.LogName.STDOUT).length();
assertTrue("STDOUT log file length for " + tce.getTaskAttemptId()
+ " is " + length + " and not <=" + LSIZE,
length <= LSIZE + truncatedMsgSize);
if (tce.isMap) {
String stderr = TestMiniMRMapRedDebugScript.readTaskLog(
LogName.STDERR, tce.getTaskAttemptId(), false);
System.out.println("STDERR log:" + stderr);
assertTrue(stderr.equals(STDERR_LOG));
}
}
} finally {
if (mr != null) {
mr.shutdown();
}
}
}
/**
* Test the truncation of DEBUGOUT file by {@link TaskLogsTruncater}
* @throws IOException
*/
@Test
@Ignore // Trunction is now done in the Child JVM, because the TaskTracker
// no longer has write access to the user log dir. MiniMRCluster
// needs to be modified to put the config params set here in a config
// on the Child's classpath
public void testDebugLogsTruncationWithMiniMR() throws IOException {
MiniMRCluster mr = null;
try {
final long LSIZE = 10000L;
JobConf clusterConf = new JobConf();
clusterConf.setLong(TaskLogsTruncater.MAP_USERLOG_RETAIN_SIZE, LSIZE);
clusterConf.setLong(TaskLogsTruncater.REDUCE_USERLOG_RETAIN_SIZE, LSIZE);
mr = new MiniMRCluster(1, "file:///", 3, null, null, clusterConf);
JobConf conf = mr.createJobConf();
Path inDir = new Path(TEST_ROOT_DIR + "/input");
Path outDir = new Path(TEST_ROOT_DIR + "/output");
FileSystem fs = FileSystem.get(conf);
if (fs.exists(outDir)) {
fs.delete(outDir, true);
}
if (!fs.exists(inDir)) {
fs.mkdirs(inDir);
}
String input = "The quick brown fox jumped over the lazy dog";
DataOutputStream file = fs.create(new Path(inDir, "part-0"));
file.writeBytes(input);
file.close();
conf.setInputFormat(TextInputFormat.class);
conf.setOutputKeyClass(LongWritable.class);
conf.setOutputValueClass(Text.class);
FileInputFormat.setInputPaths(conf, inDir);
FileOutputFormat.setOutputPath(conf, outDir);
conf.setNumMapTasks(1);
conf.setMaxMapAttempts(1);
conf.setNumReduceTasks(0);
conf.setMapperClass(TestMiniMRMapRedDebugScript.MapClass.class);
// copy debug script to cache from local file system.
Path scriptPath = new Path(TEST_ROOT_DIR, "debug-script.txt");
String debugScriptContent =
"for ((i=0;i<1000;i++)); " + "do "
+ "echo \"Lots of logs! Lots of logs! "
+ "Waiting to be truncated! Lots of logs!\";" + "done";
DataOutputStream scriptFile = fs.create(scriptPath);
scriptFile.writeBytes(debugScriptContent);
scriptFile.close();
new File(scriptPath.toUri().getPath()).setExecutable(true);
URI uri = scriptPath.toUri();
DistributedCache.createSymlink(conf);
DistributedCache.addCacheFile(uri, conf);
conf.setMapDebugScript(scriptPath.toUri().getPath());
RunningJob job = null;
try {
JobClient jc = new JobClient(conf);
job = jc.submitJob(conf);
try {
jc.monitorAndPrintJob(conf, job);
} catch (InterruptedException e) {
//
}
} catch (IOException ioe) {
} finally{
for (TaskCompletionEvent tce : job.getTaskCompletionEvents(0)) {
File debugOutFile =
TaskLog.getTaskLogFile(tce.getTaskAttemptId(), false,
TaskLog.LogName.DEBUGOUT);
if (debugOutFile.exists()) {
long length = debugOutFile.length();
assertEquals("DEBUGOUT log file length for " +
tce.getTaskAttemptId() + " is " + length + " and not " + LSIZE,
length, LSIZE + truncatedMsgSize);
}
}
}
} finally {
if (mr != null) {
mr.shutdown();
}
}
}
}