/**
* 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.datanode;
import java.io.BufferedReader;
import java.io.Closeable;
import java.io.DataOutputStream;
import java.io.File;
import java.io.FileNotFoundException;
import java.io.FileOutputStream;
import java.io.FileReader;
import java.io.IOException;
import java.io.PrintStream;
import java.lang.reflect.Method;
import java.text.DateFormat;
import java.text.SimpleDateFormat;
import java.util.Arrays;
import java.util.Collections;
import java.util.Date;
import java.util.HashMap;
import java.util.Iterator;
import java.util.List;
import java.util.Random;
import java.util.regex.Matcher;
import java.util.regex.Pattern;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.apache.hadoop.conf.Configuration;
import org.apache.hadoop.hdfs.protocol.Block;
import org.apache.hadoop.hdfs.protocol.DatanodeInfo;
import org.apache.hadoop.hdfs.protocol.LocatedBlock;
import org.apache.hadoop.hdfs.server.datanode.FSDataset.FSVolume;
import org.apache.hadoop.hdfs.server.datanode.metrics.DatanodeThreadLivenessReporter.BackgroundThread;
import org.apache.hadoop.hdfs.util.LightWeightHashSet;
import org.apache.hadoop.hdfs.util.LightWeightLinkedSet;
import org.apache.hadoop.io.IOUtils;
import org.apache.hadoop.util.StringUtils;
import org.apache.hadoop.util.DataTransferThrottler;
/**
* Performs two types of scanning:
* <li> Gets block files from the data directories and reconciles the
* difference between the blocks on the disk and in memory in
* {@link FSDataset}</li>
* <li> Scans the data directories for block files under a namespace
* and verifies that the files are not corrupt</li>
* This keeps track of blocks and their last verification times.
* Currently it does not modify the metadata for block.
*/
class DataBlockScanner {
public static final Log LOG = LogFactory.getLog(DataBlockScanner.class);
private static final int MAX_SCAN_RATE = 8 * 1024 * 1024; // 8MB per sec
private static final int MIN_SCAN_RATE = 1 * 1024 * 1024; // 1MB per sec
static final long DEFAULT_SCAN_PERIOD_HOURS = 21*24L; // three weeks
private static final long ONE_DAY = 24*3600*1000L;
private final int namespaceId;
static final DateFormat dateFormat =
new SimpleDateFormat("yyyy-MM-dd HH:mm:ss,SSS");
static final String verificationLogFile = "dncp_block_verification.log";
static final int verficationLogLimit = 5; // * numBlocks.
private long scanPeriod = DEFAULT_SCAN_PERIOD_HOURS * 3600 * 1000;
DataNode datanode;
FSDataset dataset;
// sorted set
LightWeightLinkedSet<BlockScanInfo> blockInfoSet;
HashMap<Block, BlockScanInfo> blockMap;
// processedBlocks keeps track of which blocks are scanned
// since the last run.
private LightWeightHashSet<Long> processedBlocks;
long totalScans = 0;
long totalVerifications = 0; // includes remote verification by clients.
long totalScanErrors = 0;
long totalTransientErrors = 0;
long currentPeriodStart = System.currentTimeMillis();
long bytesLeft = 0; // Bytes to scan in this period
long totalBytesToScan = 0;
private LogFileHandler verificationLog;
Random random = new Random();
DataTransferThrottler throttler = null;
static enum ScanType {
REMOTE_READ, // Verified when a block read by a client etc
VERIFICATION_SCAN, // scanned as part of periodic verfication
NONE,
}
static class BlockScanInfo implements Comparable<BlockScanInfo> {
Block block;
long lastScanTime = 0;
long lastLogTime = 0;
ScanType lastScanType = ScanType.NONE;
boolean lastScanOk = true;
BlockScanInfo(Block block) {
this.block = block;
}
public int hashCode() {
return block.hashCode();
}
public boolean equals(Object other) {
return other instanceof BlockScanInfo &&
compareTo((BlockScanInfo)other) == 0;
}
long getLastScanTime() {
return ( lastScanType == ScanType.NONE) ? 0 : lastScanTime;
}
public int compareTo(BlockScanInfo other) {
long t1 = lastScanTime;
long t2 = other.lastScanTime;
return ( t1 < t2 ) ? -1 :
(( t1 > t2 ) ? 1 : block.compareTo(other.block));
}
public String toString(){
return block.toString();
}
}
DataBlockScanner(DataNode datanode, FSDataset dataset, Configuration conf,
int namespaceId) {
this.datanode = datanode;
this.dataset = dataset;
this.namespaceId = namespaceId;
scanPeriod = conf.getInt("dfs.datanode.scan.period.hours", 0);
if ( scanPeriod <= 0 ) {
scanPeriod = DEFAULT_SCAN_PERIOD_HOURS;
}
scanPeriod *= 3600 * 1000;
LOG.info("Periodic Block Verification scan for namespace " +
namespaceId + " initialized with interval " + scanPeriod + ".");
}
int getNamespaceId() {
return namespaceId;
}
synchronized boolean isInitialized() {
return throttler != null;
}
private void updateBytesToScan(long len, long lastScanTime) {
// len could be negative when a block is deleted.
totalBytesToScan += len;
if ( lastScanTime < currentPeriodStart ) {
bytesLeft += len;
}
// Should we change throttler bandwidth every time bytesLeft changes?
// not really required.
}
private synchronized void addBlockInfo(BlockScanInfo info) {
boolean added = blockInfoSet.add(info);
blockMap.put(info.block, info);
if ( added ) {
LogFileHandler log = verificationLog;
if (log != null) {
log.setMaxNumLines(blockMap.size() * verficationLogLimit);
}
updateBytesToScan(info.block.getNumBytes(), info.lastScanTime);
}
}
private synchronized void delBlockInfo(BlockScanInfo info) {
boolean exists = blockInfoSet.remove(info);
blockMap.remove(info.block);
if ( exists ) {
LogFileHandler log = verificationLog;
if (log != null) {
log.setMaxNumLines(blockMap.size() * verficationLogLimit);
}
updateBytesToScan(-info.block.getNumBytes(), info.lastScanTime);
}
}
/** Update blockMap by the given LogEntry */
private synchronized void updateBlockInfo(LogEntry e) {
BlockScanInfo info = blockMap.get(new Block(e.blockId, 0, e.genStamp));
if(info != null && e.verificationTime > 0 &&
info.lastScanTime < e.verificationTime) {
delBlockInfo(info);
info.lastScanTime = e.verificationTime;
info.lastScanType = ScanType.VERIFICATION_SCAN;
addBlockInfo(info);
}
}
void init() throws IOException {
// get the list of blocks and arrange them in random order
Block arr[] = dataset.getBlockReport(namespaceId);
Collections.shuffle(Arrays.asList(arr));
blockInfoSet = new LightWeightLinkedSet<BlockScanInfo>();
blockMap = new HashMap<Block, BlockScanInfo>();
long scanTime = -1;
for (Block block : arr) {
BlockScanInfo info = new BlockScanInfo( block );
info.lastScanTime = scanTime--;
//still keep 'info.lastScanType' to NONE.
addBlockInfo(info);
}
/* Pick the first directory that has any existing scanner log.
* otherwise, pick the first directory.
*/
File dir = null;
FSDataset.FSVolume[] volumes = dataset.volumes.getVolumes();
for(FSDataset.FSVolume vol : volumes) {
File nsDir = vol.getNamespaceSlice(namespaceId).getDirectory();
if (LogFileHandler.isFilePresent(nsDir, verificationLogFile)) {
dir = nsDir;
break;
}
}
if (dir == null) {
dir = volumes[0].getNamespaceSlice(namespaceId).getDirectory();
}
try {
// max lines will be updated later during initialization.
verificationLog = new LogFileHandler(dir, verificationLogFile, 100);
} catch (IOException e) {
LOG.warn("Could not open verfication log. " +
"Verification times are not stored.");
}
synchronized (this) {
throttler = new DataTransferThrottler(MAX_SCAN_RATE);
}
}
private synchronized long getNewBlockScanTime() {
/* If there are a lot of blocks, this returns a random time with in
* the scan period. Otherwise something sooner.
*/
long period = Math.min(scanPeriod,
Math.max(blockMap.size(),1) * 600L * 1000L);
return System.currentTimeMillis() - scanPeriod +
random.nextInt((int)period);
}
/** Adds block to list of blocks */
synchronized void addBlock(Block block) {
if (!isInitialized()) {
return;
}
BlockScanInfo info = blockMap.get(block);
if ( info != null ) {
LOG.warn("Adding an already existing block " + block);
delBlockInfo(info);
}
info = new BlockScanInfo(block);
info.lastScanTime = getNewBlockScanTime();
addBlockInfo(info);
adjustThrottler();
}
/** Deletes the block from internal structures */
synchronized void deleteBlock(Block block) {
if (!isInitialized()) {
return;
}
BlockScanInfo info = blockMap.get(block);
if ( info != null ) {
delBlockInfo(info);
}
}
/** @return the last scan time */
synchronized long getLastScanTime(Block block) {
if (!isInitialized()) {
return 0;
}
BlockScanInfo info = blockMap.get(block);
return info == null? 0: info.lastScanTime;
}
/** Deletes blocks from internal structures */
void deleteBlocks(Block[] blocks) {
for ( Block b : blocks ) {
deleteBlock(b);
}
}
synchronized void updateScanStatus(
Block block,
ScanType type,
boolean scanOk
) {
updateScanStatusInternal(block, type, scanOk, false);
}
synchronized void updateScanStatusUpdateOnly(Block block, ScanType type, boolean scanOk) {
updateScanStatusInternal(block, type, scanOk, true);
}
/**
* @param block - block to update status for
* @param type - client, DN, ...
* @param scanOk - result of scan
* @param updateOnly - if true, cannot add a block, but only update an
* existing block
*/
private synchronized void updateScanStatusInternal(
Block block,
ScanType type,
boolean scanOk,
boolean updateOnly
) {
if (!isInitialized()) {
return;
}
BlockScanInfo info = blockMap.get(block);
if ( info != null ) {
delBlockInfo(info);
} else {
if (updateOnly) {
return;
}
// It might already be removed. Thats ok, it will be caught next time.
info = new BlockScanInfo(block);
}
long now = System.currentTimeMillis();
info.lastScanType = type;
info.lastScanTime = now;
info.lastScanOk = scanOk;
addBlockInfo(info);
if (type == ScanType.REMOTE_READ) {
totalVerifications++;
}
// Don't update meta data too often in case of REMOTE_READ
// of if the verification failed.
long diff = now - info.lastLogTime;
if (!scanOk || (type == ScanType.REMOTE_READ &&
diff < scanPeriod/3 && diff < ONE_DAY)) {
return;
}
info.lastLogTime = now;
LogFileHandler log = verificationLog;
if (log != null) {
log.appendLine(LogEntry.newEnry(block, now));
}
}
private void handleScanFailure(Block block) {
reportBadBlocks(block, namespaceId, datanode);
}
static void reportBadBlocks(Block block, int namespaceId, DataNode datanode) {
LOG.info("Reporting bad block " + block + " to namenode.");
try {
DatanodeInfo[] dnArr = { new DatanodeInfo(datanode.getDNRegistrationForNS(namespaceId)) };
LocatedBlock[] blocks = { new LocatedBlock(block, dnArr) };
datanode.reportBadBlocks(namespaceId,blocks);
} catch (IOException e){
/* One common reason is that NameNode could be in safe mode.
* Should we keep on retrying in that case?
*/
LOG.warn("Failed to report bad block " + block + " to namenode : " +
" Exception : " + StringUtils.stringifyException(e));
}
}
static private class LogEntry {
long blockId = -1;
long verificationTime = -1;
long genStamp = Block.GRANDFATHER_GENERATION_STAMP;
/**
* The format consists of single line with multiple entries. each
* entry is in the form : name="value".
* This simple text and easily extendable and easily parseable with a
* regex.
*/
private static Pattern entryPattern =
Pattern.compile("\\G\\s*([^=\\p{Space}]+)=\"(.*?)\"\\s*");
static String newEnry(Block block, long time) {
return "date=\"" + dateFormat.format(new Date(time)) + "\"\t " +
"time=\"" + time + "\"\t " +
"genstamp=\"" + block.getGenerationStamp() + "\"\t " +
"id=\"" + block.getBlockId() +"\"";
}
static LogEntry parseEntry(String line) {
LogEntry entry = new LogEntry();
Matcher matcher = entryPattern.matcher(line);
while (matcher.find()) {
String name = matcher.group(1);
String value = matcher.group(2);
try {
if (name.equals("id")) {
entry.blockId = Long.valueOf(value);
} else if (name.equals("time")) {
entry.verificationTime = Long.valueOf(value);
} else if (name.equals("genstamp")) {
entry.genStamp = Long.valueOf(value);
}
} catch(NumberFormatException nfe) {
LOG.warn("Cannot parse line: " + line, nfe);
return null;
}
}
return entry;
}
}
private synchronized void adjustThrottler() {
long timeLeft = currentPeriodStart+scanPeriod - System.currentTimeMillis();
long bw = Math.max(bytesLeft*1000/timeLeft, MIN_SCAN_RATE);
throttler.setBandwidth(Math.min(bw, MAX_SCAN_RATE));
}
private void verifyBlock(BlockScanInfo blockinfo) {
Block block = blockinfo.block;
BlockSender blockSender = null;
/* In case of failure, attempt to read second time to reduce
* transient errors. How do we flush block data from kernel
* buffers before the second read?
*/
for (int i=0; i<2; i++) {
boolean second = (i > 0);
try {
adjustThrottler();
if (!datanode.data.isValidBlock(namespaceId, block, true)) {
throw new IOException(
"Block is not a valid block or in-memroy size unmatch");
}
blockSender = new BlockSender(namespaceId, block, 0, -1, false,
false, true, datanode);
DataOutputStream out =
new DataOutputStream(new IOUtils.NullOutputStream());
blockSender.sendBlock(out, null, throttler);
LOG.info((second ? "Second " : "") +
"Verification succeeded for " + block);
if ( second ) {
totalTransientErrors++;
}
updateScanStatus(block, ScanType.VERIFICATION_SCAN, true);
return;
} catch (IOException e) {
updateScanStatus(block, ScanType.VERIFICATION_SCAN, false);
// If the block does not exists anymore, then its not an error
if ( dataset.getFile(namespaceId, block) == null ) {
LOG.info("Verification failed for " + block + ". Its ok since " +
"it not in datanode dataset anymore.");
delBlockInfo(blockinfo);
return;
}
LOG.warn((second ? "Second " : "First ") +
"Verification failed for " + block + ". Exception : " +
StringUtils.stringifyException(e));
if (second) {
totalScanErrors++;
datanode.getMetrics().blockVerificationFailures.inc();
handleScanFailure(block);
return;
}
} finally {
IOUtils.closeStream(blockSender);
datanode.getMetrics().blocksVerified.inc();
totalScans++;
totalVerifications++;
}
}
}
private synchronized long getEarliestScanTime() {
if ( blockInfoSet.size() > 0 ) {
return blockInfoSet.first().lastScanTime;
}
return Long.MAX_VALUE;
}
private synchronized boolean isFirstBlockProcessed() {
if (blockInfoSet.size() > 0 ) {
long blockId = blockInfoSet.first().block.getBlockId();
if (processedBlocks.contains(blockId)) {
return true;
}
}
return false;
}
// Picks one block and verifies it
private void verifyFirstBlock() {
BlockScanInfo block = null;
synchronized (this) {
if ( blockInfoSet.size() > 0 ) {
block = blockInfoSet.first();
}
}
if ( block != null ) {
verifyBlock(block);
processedBlocks.add(block.block.getBlockId());
}
}
/**
* Reads the current and previous log files (if any) and marks the blocks
* processed if they were processed within last scan period. Copies the log
* records of recently scanned blocks from previous to current file.
* Returns false if the process was interrupted because the thread is marked
* to exit.
*/
private boolean assignInitialVerificationTimes() {
int numBlocks = 1;
LogFileHandler log = null;
synchronized (this) {
log = verificationLog;
numBlocks = Math.max(blockMap.size(), 1);
}
long now = System.currentTimeMillis();
LogFileHandler.Reader logReader[] = new LogFileHandler.Reader[2];
try {
if (log != null) {
logReader[0] = log.new Reader(false);
logReader[1] = log.new Reader(true);
}
} catch (IOException e) {
LOG.warn("Could not read previous verification times : " +
StringUtils.stringifyException(e));
}
try {
for (LogFileHandler.Reader reader : logReader) {
// update verification times from the verificationLog.
while (reader != null && reader.hasNext()) {
if (!datanode.shouldRun
|| datanode.blockScanner.blockScannerThread.isInterrupted()) {
return false;
}
LogEntry entry = LogEntry.parseEntry(reader.next());
if (entry != null) {
updateBlockInfo(entry);
if (now - entry.verificationTime < scanPeriod) {
BlockScanInfo info = blockMap.get(new Block(entry.blockId, 0,
entry.genStamp));
if (info != null) {
if (!processedBlocks.contains(entry.blockId)) {
bytesLeft-=info.block.getNumBytes();
processedBlocks.add(entry.blockId);
}
if (reader.file == log.prevFile) {
// write the log entry to current file
// so that the entry is preserved for later runs.
log.appendLine(entry.verificationTime, entry.genStamp,
entry.blockId);
}
}
}
}
}
}
} finally {
IOUtils.closeStream(logReader[0]);
IOUtils.closeStream(logReader[1]);
}
/* Initially spread the block reads over half of
* MIN_SCAN_PERIOD so that we don't keep scanning the
* blocks too quickly when restarted.
*/
long verifyInterval = (long) (Math.min( scanPeriod/2.0/numBlocks,
10*60*1000 ));
long lastScanTime = System.currentTimeMillis() - scanPeriod;
/* Before this loop, entries in blockInfoSet that are not
* updated above have lastScanTime of <= 0 . Loop until first entry has
* lastModificationTime > 0.
*/
synchronized (this) {
if (blockInfoSet.size() > 0 ) {
BlockScanInfo info;
while ((info = blockInfoSet.first()).lastScanTime < 0) {
delBlockInfo(info);
info.lastScanTime = lastScanTime;
lastScanTime += verifyInterval;
addBlockInfo(info);
}
}
}
return true;
}
static File getCurrentFile(FSVolume vol, int namespaceId) throws IOException {
return LogFileHandler.getCurrentFile(vol.getNamespaceSlice(namespaceId).getDirectory(),
DataBlockScanner.verificationLogFile);
}
private synchronized void startNewPeriod() {
LOG.info("Starting a new period for namespaceId: " + namespaceId
+ " work left in prev period : "
+ String.format("%.2f%%", totalBytesToScan == 0 ? 0
: (bytesLeft * 100.0) / totalBytesToScan));
// reset the byte counts :
bytesLeft = totalBytesToScan;
currentPeriodStart = System.currentTimeMillis();
}
void scanNamespace() {
startNewPeriod();
// Create a new processedBlocks structure
processedBlocks = new LightWeightHashSet<Long>();
if (verificationLog != null) {
try {
verificationLog.openCurFile();
} catch (FileNotFoundException ex) {
LOG.warn("Could not open current file");
}
}
if (!assignInitialVerificationTimes()) {
return;
}
// Start scanning
scan();
}
public void scan() {
if (LOG.isDebugEnabled()) {
LOG.debug("Starting to scan namespace: " + namespaceId);
}
try {
adjustThrottler();
while (datanode.shouldRun && !Thread.interrupted()
&& datanode.isNamespaceAlive(namespaceId)
) {
datanode.updateAndReportThreadLiveness(BackgroundThread.BLOCK_SCANNER);
long now = System.currentTimeMillis();
synchronized (this) {
if ( now >= (currentPeriodStart + scanPeriod)) {
startNewPeriod();
}
}
if (((now - getEarliestScanTime()) >= scanPeriod) ||
!isFirstBlockProcessed()) {
verifyFirstBlock();
} else {
if (LOG.isDebugEnabled()) {
LOG.debug("All remaining blocks were processed recently, "
+ "so this run is complete");
}
break;
}
//TODO do we want to have breaks between blocks ?
try{
Thread.sleep(1000);
} catch (InterruptedException ignored) {}
}
} catch (RuntimeException e) {
LOG.warn("RuntimeException during DataBlockScanner.scan() : " +
StringUtils.stringifyException(e));
throw e;
} finally {
cleanUp();
if (LOG.isDebugEnabled()) {
LOG.debug("Done scanning namespace: " + namespaceId);
}
}
}
private synchronized void cleanUp() {
if (verificationLog != null) {
try {
verificationLog.roll();
} catch (IOException ex) {
LOG.warn("Received exception: ", ex);
verificationLog.close();
}
}
}
int getBlockCount(){
return blockMap.size();
}
synchronized void printBlockReport(StringBuilder buffer,
boolean summaryOnly) {
long oneHour = 3600*1000;
long oneDay = 24*oneHour;
long oneWeek = 7*oneDay;
long fourWeeks = 4*oneWeek;
int inOneHour = 0;
int inOneDay = 0;
int inOneWeek = 0;
int inFourWeeks = 0;
int inScanPeriod = 0;
int neverScanned = 0;
int total = blockInfoSet.size();
long now = System.currentTimeMillis();
Date date = new Date();
for(Iterator<BlockScanInfo> it = blockInfoSet.iterator(); it.hasNext();) {
BlockScanInfo info = it.next();
long scanTime = info.getLastScanTime();
long diff = now - scanTime;
if (diff <= oneHour) inOneHour++;
if (diff <= oneDay) inOneDay++;
if (diff <= oneWeek) inOneWeek++;
if (diff <= fourWeeks) inFourWeeks++;
if (diff <= scanPeriod) inScanPeriod++;
if (scanTime <= 0) neverScanned++;
if (!summaryOnly) {
date.setTime(scanTime);
String scanType =
(info.lastScanType == ScanType.REMOTE_READ) ? "remote" :
((info.lastScanType == ScanType.VERIFICATION_SCAN) ? "local" :
"none");
buffer.append(String.format("%-26s : status : %-6s type : %-6s" +
" scan time : " +
"%-15d %s\n", info.block,
(info.lastScanOk ? "ok" : "failed"),
scanType, scanTime,
(scanTime <= 0) ? "not yet verified" :
dateFormat.format(date)));
}
}
double pctPeriodLeft = (scanPeriod + currentPeriodStart - now)
*100.0/scanPeriod;
double pctProgress = (totalBytesToScan == 0) ? 100 :
(totalBytesToScan-bytesLeft)*10000.0/totalBytesToScan/
(100-pctPeriodLeft+1e-10);
buffer.append(String.format("\nTotal Blocks : %6d" +
"\nVerified in last hour : %6d" +
"\nVerified in last day : %6d" +
"\nVerified in last week : %6d" +
"\nVerified in last four weeks : %6d" +
"\nVerified in SCAN_PERIOD : %6d" +
"\nNot yet verified : %6d" +
"\nVerified since restart : %6d" +
"\nScans since restart : %6d" +
"\nScan errors since restart : %6d" +
"\nTransient scan errors : %6d" +
"\nCurrent scan rate limit KBps : %6d" +
"\nProgress this period : %6.0f%%" +
"\nTime left in cur period : %6.2f%%" +
"\n",
total, inOneHour, inOneDay, inOneWeek,
inFourWeeks, inScanPeriod, neverScanned,
totalVerifications, totalScans,
totalScanErrors, totalTransientErrors,
Math.round(throttler.getBandwidth()/1024.0),
pctProgress, pctPeriodLeft));
}
/**
* This class takes care of log file used to store the last verification
* times of the blocks. It rolls the current file when it is too big etc.
* If there is an error while writing, it stops updating with an error
* message.
*/
private static class LogFileHandler {
private static final String curFileSuffix = ".curr";
private static final String prevFileSuffix = ".prev";
// Don't roll files more often than this
private static final long minRollingPeriod = 6 * 3600 * 1000L; // 6 hours
private static final long minWarnPeriod = minRollingPeriod;
private static final int minLineLimit = 1000;
static File getCurrentFile(File dir, String filePrefix) {
return new File(dir, filePrefix + curFileSuffix);
}
static boolean isFilePresent(File dir, String filePrefix) {
return new File(dir, filePrefix + curFileSuffix).exists() ||
new File(dir, filePrefix + prevFileSuffix).exists();
}
private File curFile;
private File prevFile;
private int maxNumLines = -1; // not very hard limit on number of lines.
private int curNumLines = -1;
long lastWarningTime = 0;
private PrintStream out;
private final Object outLock = new Object();
int numReaders = 0;
/**
* Opens the log file for appending.
* Note that rolling will happen only after "updateLineCount()" is
* called. This is so that line count could be updated in a separate
* thread without delaying start up.
*
* @param dir where the logs files are located.
* @param filePrefix prefix of the file.
* @param maxNumLines max lines in a file (its a soft limit).
* @throws IOException
*/
LogFileHandler(File dir, String filePrefix, int maxNumLines)
throws IOException {
curFile = new File(dir, filePrefix + curFileSuffix);
prevFile = new File(dir, filePrefix + prevFileSuffix);
openCurFile();
curNumLines = -1;
setMaxNumLines(maxNumLines);
}
// setting takes affect when next entry is added.
synchronized void setMaxNumLines(int maxNumLines) {
this.maxNumLines = Math.max(maxNumLines, minLineLimit);
}
/**
* Append "\n" + line.
* If the log file need to be rolled, it will done after
* appending the text.
* This does not throw IOException when there is an error while
* appending. Currently does not throw an error even if rolling
* fails (may be it should?).
* return true if append was successful.
*/
synchronized boolean appendLine(String line) {
synchronized(this.outLock) {
if (out == null) {
try {
openCurFile();
} catch (FileNotFoundException ex) {
LOG.warn("Could not open current file");
return false;
}
}
out.println();
out.print(line);
}
curNumLines += (curNumLines < 0) ? -1 : 1;
try {
rollIfRequired();
} catch (IOException e) {
warn("Rolling failed for " + curFile + " : " + e.getMessage());
return false;
}
return true;
}
boolean appendLine(long verificationTime, long genStamp, long blockId) {
return appendLine("date=\""
+ dateFormat.format(new Date(verificationTime)) + "\"\t " + "time=\""
+ verificationTime + "\"\t " + "genstamp=\"" + genStamp + "\"\t "
+ "id=\"" + blockId + "\"");
}
//warns only once in a while
synchronized private void warn(String msg) {
long now = System.currentTimeMillis();
if ((now - lastWarningTime) >= minWarnPeriod) {
lastWarningTime = now;
LOG.warn(msg);
}
}
private void openCurFile() throws FileNotFoundException {
synchronized(this.outLock) {
close();
out = new PrintStream(new FileOutputStream(curFile, true));
}
}
//This reads the current file and updates the count.
void updateCurNumLines() {
int count = 0;
Reader it = null;
try {
for(it = new Reader(true); it.hasNext(); count++) {
it.next();
}
} catch (IOException e) {
} finally {
synchronized (this) {
curNumLines = count;
}
IOUtils.closeStream(it);
}
}
private void rollIfRequired() throws IOException {
if (curNumLines < maxNumLines || numReaders > 0) {
return;
}
long now = System.currentTimeMillis();
if (now < minRollingPeriod) {
return;
}
roll();
openCurFile();
updateCurNumLines();
}
private void roll() throws IOException {
if (LOG.isDebugEnabled()) {
LOG.debug("Rolling current file: " + curFile.getAbsolutePath()
+ " to previous file: " + prevFile.getAbsolutePath());
}
if (!prevFile.delete() && prevFile.exists()) {
throw new IOException("Could not delete " + prevFile);
}
close();
if (!curFile.renameTo(prevFile)) {
openCurFile();
throw new IOException("Could not rename " + curFile +
" to " + prevFile);
}
}
void close() {
synchronized(this.outLock) {
if (out != null) {
out.close();
out = null;
}
}
}
/**
* This is used to read the lines in order.
* If the data is not read completely (i.e, untill hasNext() returns
* false), it needs to be explicitly
*/
private class Reader implements Iterator<String>, Closeable {
BufferedReader reader;
File file;
String line;
boolean closed = false;
private Reader(boolean skipPrevFile) throws IOException {
synchronized (LogFileHandler.this) {
numReaders++;
}
reader = null;
file = (skipPrevFile) ? curFile : prevFile;
readNext();
}
private boolean openFile() throws IOException {
for(int i=0; i<2; i++) {
if (reader != null || i > 0) {
// move to next file
file = (file == prevFile) ? curFile : null;
}
if (file == null) {
return false;
}
if (file.exists()) {
break;
}
}
if (reader != null ) {
reader.close();
reader = null;
}
reader = new BufferedReader(new FileReader(file));
return true;
}
// read next line if possible.
private void readNext() throws IOException {
line = null;
try {
if (reader != null && (line = reader.readLine()) != null) {
return;
}
if (line == null) {
// move to the next file.
if (openFile()) {
readNext();
}
}
} finally {
if (!hasNext()) {
close();
}
}
}
public boolean hasNext() {
return line != null;
}
public String next() {
String curLine = line;
try {
readNext();
} catch (IOException e) {
LOG.info("Could not reade next line in LogHandler : " +
StringUtils.stringifyException(e));
}
return curLine;
}
public void remove() {
throw new RuntimeException("remove() is not supported.");
}
public void close() throws IOException {
if (!closed) {
try {
if (reader != null) {
reader.close();
}
} finally {
file = null;
reader = null;
closed = true;
synchronized (LogFileHandler.this) {
numReaders--;
assert(numReaders >= 0);
}
}
}
}
}
}
}