天天看點
傳回

叢集中某一個節點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>

我看了一下我的項目中：

叢集中某一個節點logback日志檔案寫入不成功排查曆程
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

舉例來說：

叢集中某一個節點logback日志檔案寫入不成功排查曆程

這個樹狀的 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 如下圖所示：

叢集中某一個節點logback日志檔案寫入不成功排查曆程

按照我個人的了解：

<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>();
}

再來看繼承體系：

叢集中某一個節點logback日志檔案寫入不成功排查曆程

我們常用的

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 方法處：

叢集中某一個節點logback日志檔案寫入不成功排查曆程

此時調用堆棧如下圖所示：

叢集中某一個節點logback日志檔案寫入不成功排查曆程

2、

ch.qos.logback.core.AsyncAppenderBase

第 265 行，内部類

Worker

的

run

方法内的循環處:

叢集中某一個節點logback日志檔案寫入不成功排查曆程
内部類

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 時的調用棧資訊：

叢集中某一個節點logback日志檔案寫入不成功排查曆程

我遇到的問題就在這個 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 方法捕獲了：

叢集中某一個節點logback日志檔案寫入不成功排查曆程

然後，真正寫入日志的方法沒有被執行，即

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));
    }
}

然後，我們可以看一下發生異常的棧資訊：

叢集中某一個節點logback日志檔案寫入不成功排查曆程

我選擇從

ch.qos.logback.core.rolling.FixedWindowRollingPolicy

繼續細化分析問題：

叢集中某一個節點logback日志檔案寫入不成功排查曆程

這行還有 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日志檔案寫入不成功排查曆程

如圖所示，logback 中自制的分詞器将

biz-%d{yyyy-MM-dd_HH}.%i.txt

解析成了 tokenList。

接下來代碼執行到第 67 行，看一下 Node 的結果：

叢集中某一個節點logback日志檔案寫入不成功排查曆程

%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性能優化及源碼分析 閱讀

wildfly jboss slf4j logback
上一篇: 更改ubuntu的系統語言
下一篇: 你應該知道的ConcurrentSkipListMap的細節

繼續閱讀