集群中某一个节点logback日志文件写入不成功排查历程
问题背景
我的日志路径是 /opt/logs/xxxx.log
,集群中共有两台服务器:
- 一台服务器的日志文件最新更新时间 是今天,
- 另一台服务器的日志文件最新更新时间 却是昨天甚至更久之前。
换言之,一台服务器从过去某个时间点开始,日志就不能正常打印了。另外,交代一下,这个项目不是我从零开始搭建的,是我接手维护的项目。我使用的日志框架是 slf4j + logback。
一开始,我在百度上找的解决方案:
<?xml version="1.0" encoding="UTF-8"?>
<jboss-deployment-structure>
<deployment>
<!-- Exclusions allow you to prevent the server from automatically adding some dependencies -->
<exclusions>
<module name="org.slf4j" />
<module name="org.slf4j.impl" />
<!-- 如果项目中用到jcl-over-slf4j,可以将下面这个module也毙了 -->
<module name="org.slf4j.jcl-over-slf4j" />
</exclusions>
</deployment>
</jboss-deployment-structure>
我看了一下我的项目中:
jcl-over-slf4j jul-to-slf4j log4j-over-slf4j slf4j-api 都有,于是我试了一下
遗憾的是,问题没能解决,只好继续分析,我也猜不到原因,又看不到报错,所以就想着能不能在源码里找到一些对解决问题有帮助的异常。
源码分析
例如,我们有一个简单的 UserService 的例子,调用了 log.info 方法:
package service;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class UserService {
private static final Logger log = LoggerFactory.getLogger("service.UserService");
public String getPhoneByUsername(String username) {
String result = "12345678901";
log.info("{}'s phone number is {}", username, result);
return result;
}
}
logback 中实现 org.slf4j.Logger 接口的实例是类 ch.qos.logback.classic.Logger
。我们发现它的 trace/debug/info/warn/error 方法,都会调用私有方法 buildLoggingEventAndAppend :
private void buildLoggingEventAndAppend(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params,
final Throwable t) {
// 创建一个 LoggingEvent 对象
LoggingEvent le = new LoggingEvent(localFQCN, this, level, msg, t, params);
le.setMarker(marker);
// 调用 Appenders 来处理 LoggingEvent
callAppenders(le);
}
接下来,来看 callAppenders 的源码:
/**
* Invoke all the appenders of this logger.
*
* @param event
* The event to log
*/
public void callAppenders(ILoggingEvent event) {
int writes = 0;
for (Logger l = this; l != null; l = l.parent) {
writes += l.appendLoopOnAppenders(event);
if (!l.additive) {
break;
}
}
// No appenders in hierarchy
if (writes == 0) {
loggerContext.noAppenderDefinedWarning(this);
}
}
我们来看这个循环 for (Logger l = this; l != null; l = l.parent) { }
,这里从当前 Logger 向上查找父 Logger,拿 service.userService
举例来说:
这个树状的 Logger 结构,是在 LoggerFactory.getLogger("service.UserService")
时创建的。在 logback 中,类 ch.qos.logback.classic.LoggerContext#getLogger
承担了该任务。
ch.qos.logback.classic.Logger
的代码继续往下挖,到了 appendLoopOnAppenders
方法,这个方法能否继续执行,关键就是 aai
是否为 null ?
transient private AppenderAttachableImpl<ILoggingEvent> aai;
private int appendLoopOnAppenders(ILoggingEvent event) {
if (aai != null) {
return aai.appendLoopOnAppenders(event);
} else {
return 0;
}
}
依然是 ch.qos.logback.classic.Logger
的源码,aai
是在 addAppender 的时候创建的,如果Logger没有一个appender,aai就是null:
public synchronized void addAppender(Appender<ILoggingEvent> newAppender) {
if (aai == null) {
aai = new AppenderAttachableImpl<ILoggingEvent>();
}
aai.addAppender(newAppender);
}
来看一下我的配置,位于 resources 文件夹下的 logback.xml:
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<!-- 这里我粘贴的是官方的配置,没有粘贴我排查出问题的配置 -->
<file>logFile.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<!-- daily rollover -->
<fileNamePattern>logFile.%d{yyyy-MM-dd}.log</fileNamePattern>
<!-- keep 30 days' worth of history capped at 3GB total size -->
<maxHistory>30</maxHistory>
<totalSizeCap>3GB</totalSizeCap>
</rollingPolicy>
<encoder>
<pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
</encoder>
</appender>
<appender name="ASYNC_FILE" class="ch.qos.logback.classic.AsyncAppender">
<appender-ref ref="FILE"/>
</appender>
<root level="INFO">
<appender-ref ref="ASYNC_FILE"/>
</root>
</configuration>
根据上面的 xml 配置,解析得到的 root logger 如下图所示:
按照我个人的理解:<logger>
标签支持 <append-ref>
子标签,如果它包含至少一个 <append-ref>
,那么该 Logger 就有 aai 属性。
另外,ch.qos.logback.classic.AsyncAppender
自带 aai
,则是因为它的父类 ch.qos.logback.core.AsyncAppenderBase
有 aai
:
public class AsyncAppenderBase<E> extends UnsynchronizedAppenderBase<E> implements AppenderAttachable<E> {
AppenderAttachableImpl<E> aai = new AppenderAttachableImpl<E>();
}
再来看继承体系:
我们常用的 ConsoleAppender
, FileAppender
, RollingFileAppender
这些是没有 aai
属性的!
现在,我们回到 ch.qos.logback.core.spi.AppenderAttachableImpl
源码中的 appendLoopOnAppenders
方法,它调用了 doAppend
/**
* Call the <code>doAppend</code> method on all attached appenders.
*/
public int appendLoopOnAppenders(E e) {
int size = 0;
for (Appender<E> appender : appenderList) {
appender.doAppend(e);
size++;
}
return size;
}
调试关键点
AsyncAppender
如果想弄清楚 AsyncAppender 的异步工作过程,建议断点打在两处:
1、ch.qos.logback.core.AsyncAppenderBase
第 156 行,put 方法处:
此时调用堆栈如下图所示:
2、ch.qos.logback.core.AsyncAppenderBase
第 265 行,内部类 Worker
的 run
方法内的循环处:
内部类
Worker
工作的线程名是以AsyncAppender-Worker-
为前缀的。
RollingFileAppender
现在,我们把断点放在 ch.qos.logback.core.rolling.RollingFileAppender
的 222 行,看一下 subAppend
的执行:
/**
* This method differentiates RollingFileAppender from its super class.
*/
@Override
protected void subAppend(E event) {
// The roll-over check must precede actual writing. This is the
// only correct behavior for time driven triggers.
// We need to synchronize on triggeringPolicy so that only one rollover
// occurs at a time
synchronized (triggeringPolicy) {
if (triggeringPolicy.isTriggeringEvent(currentlyActiveFile, event)) {
rollover();
}
}
// 调用父类 OutputStreamAppender 的 subAppend 方法,这个父类方法是实际发生写入的方法,如果不执行就没法正常写入日志!
super.subAppend(event);
}
下图是我运行到 subAppend 时的调用栈信息:
我遇到的问题就在这个 rollover
我先贴一下,我有问题的 logback.xml
:
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>logFile.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
<FileNamePattern>biz-%d{yyyy-MM-dd_HH}.%i.txt</FileNamePattern>
<MinIndex>1</MinIndex>
<!-- 最多保留20份历史日志 -->
<MaxIndex>20</MaxIndex>
</rollingPolicy>
<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
<!-- 每个文件最大1KB,这里是为了测试才改成 1KB 的 -->
<MaxFileSize>1KB</MaxFileSize>
</triggeringPolicy>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>%date{yyyy-MM-dd HH:mm:ss.SSS} %level [%thread] %logger{36} %msg%n</pattern>
</encoder>
</appender>
<appender name="ASYNC_FILE" class="ch.qos.logback.classic.AsyncAppender">
<appender-ref ref="FILE"/>
</appender>
<root level="INFO">
<appender-ref ref="ASYNC_FILE"/>
</root>
</configuration>
然后,我把打印日志的方法 UserService#getPhoneByUsername
循环执行个 200 次:
for (int i = 0; i < 100; i++) {
String result = getPhoneByUsername("Mi");
}
ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy
的 isTriggeringEvent 方法返回了 true,这就和我那台不打印日志的服务器的情况一样了:
public boolean isTriggeringEvent(final File activeFile, final E event) {
long now = System.currentTimeMillis();
if (invocationGate.isTooSoon(now))
return false;
// 当日志文件大小超过了设置的大小(默认是 10MB,我这里改成了 1KB),则返回true
return (activeFile.length() >= maxFileSize.getSize());
}
断点可以设置在 rollover
这个方法所在行。接下来,当文件大小超过指定大小,调用 rollback 时出现了异常,这个异常被 ch.qos.logback.core.UnsynchronizedAppenderBase
的 doAppend 方法捕获了:
然后,真正写入日志的方法没有被执行,即 ch.qos.logback.core.OutputStreamAppender
的 subAppend
方法没有被执行:
/**
* Actual writing occurs here.
* <p>
* Most subclasses of <code>WriterAppender</code> will need to override this
* method.
*
* @since 0.9.0
*/
protected void subAppend(E event) {
if (!isStarted()) {
return;
}
try {
// this step avoids LBCLASSIC-139
if (event instanceof DeferredProcessingAware) {
((DeferredProcessingAware) event).prepareForDeferredProcessing();
}
// the synchronization prevents the OutputStream from being closed while we
// are writing. It also prevents multiple threads from entering the same
// converter. Converters assume that they are in a synchronized block.
lock.lock();
try {
writeOut(event);
} finally {
lock.unlock();
}
} catch (IOException ioe) {
// as soon as an exception occurs, move to non-started state
// and add a single ErrorStatus to the SM.
this.started = false;
addStatus(new ErrorStatus("IO failure in appender", this, ioe));
}
}
然后,我们可以看一下发生异常的栈信息:
我选择从 ch.qos.logback.core.rolling.FixedWindowRollingPolicy
继续细化分析问题:
这行还有 fileNamePattern 这个变量名,让我联想到了 xml 中 的 <FileNamePattern>
标签。
模拟出错的地方FileNamePattern
然后我就专门写了一段代码来模拟 FileNamePattern 的行为:
FileNamePattern pattern = new FileNamePattern("biz-%d{yyyy-MM-dd_HH}.%i.txt", new LoggerContext());
String s = pattern.convertInt(1);
调试参考点
断点打在 ch.qos.logback.core.rolling.helper.FileNamePattern
第 65 行,看 parse 方法第 64 行的结果:
如图所示,logback 中自制的分词器将 biz-%d{yyyy-MM-dd_HH}.%i.txt
解析成了 tokenList。
接下来代码执行到第 67 行,看一下 Node 的结果:
%d{yyyy-MM-dd_HH}
和 %i
被解析成了关键字,其他则保持字面值。
关键字 d 和 i 对应不同的转换器:
static final Map<String, String> CONVERTER_MAP = new HashMap<String, String>();
static {
// i 对应 IntegerTokenConverter
CONVERTER_MAP.put(IntegerTokenConverter.CONVERTER_KEY, IntegerTokenConverter.class.getName());
// d 对应 DateTokenConverter
CONVERTER_MAP.put(DateTokenConverter.CONVERTER_KEY, DateTokenConverter.class.getName());
}
又因为 FixedWindowRollingPolicy
产生的参数值只有 Integer 型的,所以遇到 %d{yyyy-MM-dd_HH}
就会出错。
至此“结案”了!
解决方案
这个可以求教官方文档 阅读,解决 FileNamePattern 和 rollingPolicy 不匹配的问题。
FixedWindowRollingPolicy
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>logFile.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
<!-- 修改的部分 Begin-->
<FileNamePattern>biz.%i.txt</FileNamePattern>
<!-- 修改的部分 END -->
<MinIndex>1</MinIndex>
<!-- 最多保留20份历史日志 -->
<MaxIndex>20</MaxIndex>
</rollingPolicy>
<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
<!-- 每个文件最大1KB,这里是为了测试才改成 1KB 的 -->
<MaxFileSize>1KB</MaxFileSize>
</triggeringPolicy>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>%date{yyyy-MM-dd HH:mm:ss.SSS} %level [%thread] %logger{36} %msg%n</pattern>
</encoder>
</appender>
<appender name="ASYNC_FILE" class="ch.qos.logback.classic.AsyncAppender">
<appender-ref ref="FILE"/>
</appender>
<root level="INFO">
<appender-ref ref="ASYNC_FILE"/>
</root>
</configuration>
SizeAndTimeBasedRollingPolicy
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>logFile.log</file>
<!-- 修改的部分 Begin-->
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<!-- rollover daily -->
<fileNamePattern>biz-%d{yyyy-MM-dd_HH}.%i.txt</fileNamePattern>
<!-- each file should be at most 100MB, keep 60 days worth of history, but at most 20GB -->
<maxFileSize>100MB</maxFileSize>
<maxHistory>60</maxHistory>
<totalSizeCap>20GB</totalSizeCap>
</rollingPolicy>
<!-- 修改的部分 END -->
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>%date{yyyy-MM-dd HH:mm:ss.SSS} %level [%thread] %logger{36} %msg%n</pattern>
</encoder>
</appender>
<appender name="ASYNC_FILE" class="ch.qos.logback.classic.AsyncAppender">
<appender-ref ref="FILE"/>
</appender>
<root level="INFO">
<appender-ref ref="ASYNC_FILE"/>
</root>
</configuration>
总结
我的一台服务器的日志文件 logFile.log 小于设置的 MaxFileSize(50MB),因此可以正常工作;
另一台服务器的日志文件大小大于 MaxFileSize,在执行 rollback 方法时出错,导致无法继续正常写入日志。
而导致 rollback 不能正常工作的原因是 FileNamePattern 和 rollingPolicy 不匹配。
参考文档
logback Manual -- Chapter 4: Appenders 阅读
jboss logback slf4j 日志文件不生成问题 阅读
logback性能优化及源码分析 阅读