叢集中某一個節點日誌檔案寫入不成功排查歷程
問題背景
我的日誌路徑是 /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}
就會出錯。
至此“結案”了!
總結
我的一臺伺服器的日誌檔案logFile.log小於設定的MaxFileSize(50MB),因此可以正常工作,
另一臺伺服器的日誌檔案大小大於MaxFileSize,在執行 rollback 方法時出錯,導致無法繼續正常寫入日誌。
而導致 rollback 不能正常工作的原因是 FileNamePattern 和 rollingPolicy 不匹配。
參考文件
logback Manual -- Chapter 4: Appenders 閱讀
jboss logback slf4j 日誌檔案不生成問題 閱讀
logback效能優化及原始碼分析 閱讀