在使用slf4j的logback实现时,使用TimeBasedRollingPolicy根据时间滚动日志策略并使用RollingFileAppender进行日志滚动,多进程共用同一个日志文件时,会出现较多xxxxxx.tmp文件未删除的情况。
出现tmp文件的条件: 使用TimeBasedRollingPolicy/RollingFileAppender配置,并启用压缩,并配置的<file></file>标签名称与滚动名称模板不同(如打印日志时文件名为demo.log,归档时文件名demo.2019-12-12.log.gz),并且单应用启动多实例共用一个日志文件作为输出,例如:
<appender name="File"
class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${LOG_HOME}/demo.log</file>
<rollingPolicy
class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<FileNamePattern>${LOG_HOME}/demo.log.%d{yyyy-MM-dd}.log.gz
</FileNamePattern>
<MaxHistory>30</MaxHistory>
</rollingPolicy>
<encoder
class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{50} - %msg%n</pattern>
</encoder>
</appender>
多进程将日志输出到同一个日志文件logback是允许的,仅输出也不会出现问题,但是当归档时,多个进程同时归档,原文件与目标文件(归档文件)名称不同时,会首先关闭输出流,然后将原日志文件rename为xxx.timestamp.tmp,然后读取tmp文件输出到目标归档文件,此时如果是多进程,其他进程那一时刻很有可能没有关闭输出流,所以tmp文件内容一致再增加,并且当其他进程开始归档时也会同样的流程创建tmp文件,然是创建tmp文件后,后续判断归档文件已存在,直接返回了,导致tmp文件未被删除。
解决方法:
1. 不压缩(但是多进程也存在问题,日志输出混乱,某个时间点的日志可能出现在上一个时间点日志文件内)
2. 删除<file>xxx</file>标签,此时产生的日志文件名与归档文件名相同(归档文件后缀.gz/zip),不需要创建临时文件,直接压缩原文件,压缩完毕会删除原文件(可能会丢日志,因为其他进程还在往里面写)
3. 多进程配置不同的logback配置文件,日志分开存储
4. appender标签启用<prudent>true</prudent>, logback允许多jvm使用同一个log日志,启用该标志会加锁,在日志输出每秒<100条时性能影响不大,但是不使用该功能要比使用该功能日志性能高3倍左右。局限性就是不能日志使用压缩功能,不能使用<file>标签指定日志文件名,详细参考:prudent prudentWithRolling
源码解析如下:
//RollingFileAppender
public void rollover() {
//加锁,统一进程同一时刻只会有一个归档操作
lock.lock();
try {
//关闭日志输出流
this.closeOutputStream();
//归档,删除过期文件(如保留30天内,则超过30天的文件被删除)
attemptRollover();
//重新创建或打开日志文件,并设置输出流
attemptOpenFile();
} finally {
lock.unlock();
}
}
private void attemptRollover() {
try {
//调用滚动策略滚动归档日志
rollingPolicy.rollover();
} catch (RolloverFailure rf) {
addWarn("RolloverFailure occurred. Deferring roll-over.");
// we failed to roll-over, let us not truncate and risk data loss
this.append = true;
}
}
//TimeBasedRollingPolicy 1.1.7
public void rollover() throws RolloverFailure {
//该方法被执行时,会认为日志文件为已关闭
String elapsedPeriodsFileName = timeBasedFileNamingAndTriggeringPolicy.getElapsedPeriodsFileName();
String elapsedPeriodStem = FileFilterUtil.afterLastSlash(elapsedPeriodsFileName);
//压缩模式,FileNamePattern标签对应的文件后缀,.gz .zip,否则不压缩
if (compressionMode == CompressionMode.NONE) {
//获取file标签是否配置,如果配置了,则将原文件重命名为归档文件
if (getParentsRawFileProperty() != null) {
renameUtil.rename(getParentsRawFileProperty(), elapsedPeriodsFileName);
} // else { nothing to do if CompressionMode == NONE and parentsRawFileProperty == null }
} else {
//file标签没有配置,直接将原文件压缩为目标归档文件
if (getParentsRawFileProperty() == null) {
compressionFuture = compressor.asyncCompress(elapsedPeriodsFileName, elapsedPeriodsFileName, elapsedPeriodStem);
} else {
//配置了file标签则需要先重命名为tmp,然后读取tmp输出到归档压缩文件
compressionFuture = renamedRawAndAsyncCompress(elapsedPeriodsFileName, elapsedPeriodStem);
}
}
//删除过期文件
if (archiveRemover != null) {
Date now = new Date(timeBasedFileNamingAndTriggeringPolicy.getCurrentTime());
cleanUpFuture = archiveRemover.cleanAsynchronously(now);
}
}
//重命名并压缩归档
Future<?> renamedRawAndAsyncCompress(String nameOfCompressedFile, String innerEntryName) throws RolloverFailure {
String parentsRawFile = getParentsRawFileProperty();
//tmp文件名
String tmpTarget = parentsRawFile + System.nanoTime() + ".tmp";
//重命名
renameUtil.rename(parentsRawFile, tmpTarget);
//异步压缩
return compressor.asyncCompress(tmpTarget, nameOfCompressedFile, innerEntryName);
}
//Compressor 异步压缩
public Future<?> asyncCompress(String nameOfFile2Compress, String nameOfCompressedFile, String innerEntryName) throws RolloverFailure {
//参数:原文件,归档文件
CompressionRunnable runnable = new CompressionRunnable(nameOfFile2Compress, nameOfCompressedFile, innerEntryName);
ExecutorService executorService = context.getExecutorService();
//提交线程池
Future<?> future = executorService.submit(runnable);
return future;
}
// 压缩
public void compress(String nameOfFile2Compress, String nameOfCompressedFile, String innerEntryName) {
//gz zip压缩
switch (compressionMode) {
case GZ:
gzCompress(nameOfFile2Compress, nameOfCompressedFile);
break;
case ZIP:
zipCompress(nameOfFile2Compress, nameOfCompressedFile, innerEntryName);
break;
case NONE:
throw new UnsupportedOperationException("compress method called in NONE compression mode");
}
}
private void gzCompress(String nameOfFile2gz, String nameOfgzedFile) {
File file2gz = new File(nameOfFile2gz);
//原文件不存在直接返回,注意此时tmp文件没有被删除
if (!file2gz.exists()) {
addStatus(new WarnStatus("The file to compress named [" + nameOfFile2gz + "] does not exist.", this));
return;
}
//如果没有gz后缀,则加个后缀
if (!nameOfgzedFile.endsWith(".gz")) {
nameOfgzedFile = nameOfgzedFile + ".gz";
}
//归档文件
File gzedFile = new File(nameOfgzedFile);
//归档文件是否存在,已存在直接返回,注意此时tmp文件没有被删除
if (gzedFile.exists()) {
addWarn("The target compressed file named [" + nameOfgzedFile + "] exist already. Aborting file compression.");
return;
}
addInfo("GZ compressing [" + file2gz + "] as [" + gzedFile + "]");
createMissingTargetDirsIfNecessary(gzedFile);
BufferedInputStream bis = null;
GZIPOutputStream gzos = null;
//读取tmp文件输出到归档文件
try {
bis = new BufferedInputStream(new FileInputStream(nameOfFile2gz));
gzos = new GZIPOutputStream(new FileOutputStream(nameOfgzedFile));
byte[] inbuf = new byte[BUFFER_SIZE];
int n;
while ((n = bis.read(inbuf)) != -1) {
gzos.write(inbuf, 0, n);
}
bis.close();
bis = null;
gzos.close();
gzos = null;
//删除临时文件,这个地方有个问题如果上面抛异常了,tmp文件依旧删不掉
//1.3.0版本该部分移到了try-catch后面
if (!file2gz.delete()) {
addStatus(new WarnStatus("Could not delete [" + nameOfFile2gz + "].", this));
}
} catch (Exception e) {
addStatus(new ErrorStatus("Error occurred while compressing [" + nameOfFile2gz + "] into [" + nameOfgzedFile + "].", this, e));
} finally {
if (bis != null) {
try {
bis.close();
} catch (IOException e) {
// ignore
}
}
if (gzos != null) {
try {
gzos.close();
} catch (IOException e) {
// ignore
}
}
}
}