logback日誌不列印到檔案問題深入剖析
阿新 • • 發佈:2019-01-10
詳細探究logback不列印日誌到檔案的問題分析與案例演示,並提供官網bug的提交連結
環境與配置
使用maven構建的,引入logback依賴如下:(注:其他依賴已經排除了其他日誌框架的依賴,故不存在日誌框架衝突問題 – 這也是一個點哦)
<!-- logback -->
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-classic</artifactId >
<version>1.1.2</version>
</dependency>
logback.xml
配置如下:(以下是真實線上環境的配置哦,把敏感資訊換成了TEST
)
<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="false">
<!--<property name="log.base" value="${log_dir}/" />-->
<property name ="log.base" value="D:/" /><!--配置日誌輸出路徑(測試配置)-->
<!-- 控制檯輸出 -->
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n
</pattern >
</encoder>
</appender>
<!-- 按照每天生成錯誤日誌檔案 -->
<appender name="ERRORFILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<Prudent>true</Prudent>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<!--日誌檔案輸出的檔名 -->
<FileNamePattern>${log.base}TEST_ERROR-%d{yyyy-MM-dd}.log</FileNamePattern>
<!--日誌檔案保留天數 -->
<MaxHistory>5</MaxHistory>
</rollingPolicy>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<!--格式化輸出:%d表示日期,%thread表示執行緒名,%-5level:級別從左顯示5個字元寬度%msg:日誌訊息,%n是換行符 -->
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n
</pattern>
</encoder>
<filter class="ch.qos.logback.classic.filter.LevelFilter"><!-- 只打印錯誤日誌 -->
<level>ERROR</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
</appender>
<!-- 按照每天生成警告日誌檔案 -->
<appender name="WARNFILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<Prudent>true</Prudent>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<!--日誌檔案輸出的檔名 -->
<FileNamePattern>${log.base}TEST_WARN-%d{yyyy-MM-dd}.log</FileNamePattern>
<!--日誌檔案保留天數 -->
<MaxHistory>5</MaxHistory>
</rollingPolicy>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<!--格式化輸出:%d表示日期,%thread表示執行緒名,%-5level:級別從左顯示5個字元寬度%msg:日誌訊息,%n是換行符 -->
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n
</pattern>
</encoder>
<filter class="ch.qos.logback.classic.filter.LevelFilter"><!-- 只打印警告日誌 -->
<level>WARN</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
</appender>
<!-- 按照每天生成INFO日誌檔案 -->
<appender name="INFOFILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<Prudent>true</Prudent>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<!--日誌檔案輸出的檔名 -->
<FileNamePattern>${log.base}TEST_INFO-%d{yyyy-MM-dd}.log</FileNamePattern>
<!--日誌檔案保留天數 -->
<MaxHistory>5</MaxHistory>
</rollingPolicy>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<!--格式化輸出:%d表示日期,%thread表示執行緒名,%-5level:級別從左顯示5個字元寬度%msg:日誌訊息,%n是換行符 -->
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n
</pattern>
</encoder>
<filter class="ch.qos.logback.classic.filter.LevelFilter"><!-- 只打印INFO日誌 -->
<level>INFO</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
</appender>
<!-- 按照每天生成DEBUG日誌檔案 -->
<appender name="DEBUGFILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<Prudent>true</Prudent>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<!--日誌檔案輸出的檔名 -->
<FileNamePattern>${log.base}TEST_DEBUG-%d{yyyy-MM-dd}.log</FileNamePattern>
<!--日誌檔案保留天數 -->
<MaxHistory>5</MaxHistory>
</rollingPolicy>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<!--格式化輸出:%d表示日期,%thread表示執行緒名,%-5level:級別從左顯示5個字元寬度%msg:日誌訊息,%n是換行符 -->
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n
</pattern>
</encoder>
<filter class="ch.qos.logback.classic.filter.LevelFilter"><!-- 只打印DEBUG日誌 -->
<level>DEBUG</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
</appender>
<!-- 日誌輸出級別 -->
<root level="DEBUG">
<appender-ref ref="STDOUT" />
<appender-ref ref="ERRORFILE" />
<appender-ref ref="WARNFILE" />
<appender-ref ref="INFOFILE" />
<appender-ref ref="DEBUGFILE" />
</root>
</configuration>
問題
- 一次排查線上系統的問題時發現logback存在日誌不輸出的情況,導致無法通過有效日誌排查出現的問題。
- 會發現其實有日誌輸出,但某些日誌就是不能輸出,從大方向上來看是日誌有遺漏了
- 想想logback也沒有配置過濾日誌的情況
- 查資料,各個部落格網站都沒有相關案例,未有的幾個類似問題都與我的環境不一樣,故排除他們的情況
解決
先說解決方案吧,1.1.2
版本的logback存在bug,導致日誌不輸出。。。所以解決方案就是提高版本。
下面說下bug吧
原因
設定prudent屬性為true的FileAppender當執行緒被interrupt後,之後的日誌都不會列印了。
這是logback官網1.3版本釋出時解決的一個bug。提交bug的原作者描述bug如下:
If a thread is ever interrupted immediately followed by a logging call using a prudent FileAppender then the FileAppender is stopped and no logging can be done by any other thread.
FileLockInterruptedException is thrown by FileChannel.lock used in FileAppender.safeWrite. This exception should not stop the entire appender, for my use cases it would be enough to just catch the exception and reset the interrupted flag.
I've attached a very simple unit test that demonstrates this issue.
簡單理解就是執行緒被中斷後,後面的日誌都不會列印,包括其他執行緒。並且也給出了復現案例,我參照它的描述頁設計了一下,確實如此。
測試原始碼
採用多種執行緒測試,兩個執行緒,對一中一個執行緒在一定條件後進行interrupt(),觀察日誌輸出檔案的輸出情況
【測試logback日誌不輸出原始碼】
若要測試注意自己logback.xml檔案路勁即可
package com.bonree.utils;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.joran.JoranConfigurator;
import ch.qos.logback.core.joran.spi.JoranException;
import ch.qos.logback.core.util.StatusPrinter;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import java.io.File;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.TimeUnit;
public class TestA {
static ScheduledExecutorService threadPool = Executors.newScheduledThreadPool(5);
static ScheduledExecutorService singleThreadPool = Executors.newSingleThreadScheduledExecutor();
private final static String confPath = "D:\\IDEAtest\\SDK_Server\\conf\\logback.xml";
static ExecutorService fixedThreadPool = Executors.newFixedThreadPool(5);
public static void main(String[] args) {
System.out.println("start ----");
initLogback(); // 初始化logback
ARunnable aRunnable1 = new ARunnable("a-n-1", false, -1);
ARunnable aRunnable2 = new ARunnable("a-n-2", true, 5);
BRunnable bRunnable1 = new BRunnable("b-n-1", false, -1);
BRunnable bRunnable2 = new BRunnable("b-n-2", true, 7);
// testUseScheduledThreadPool(aRunnable1, aRunnable2);
// testUseThread(bRunnable1,bRunnable2);
testFixedThreadPool(bRunnable1,bRunnable2);
}
/**載入logback配置資訊*/
public static void initLogback() {
//載入 logback配置資訊
try {
LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory();
JoranConfigurator configurator = new JoranConfigurator();
configurator.setContext(lc);
lc.reset();
configurator.doConfigure(confPath);
StatusPrinter.printInCaseOfErrorsOrWarnings(lc);
} catch (JoranException e) {
e.printStackTrace();
System.out.println("sync logback.xml error! "+ e.getMessage());
System.exit(0);
}
}
/**使用執行緒池ScheduledThreadPool測試*/
public static void testUseScheduledThreadPool(Runnable aRunnable1, Runnable aRunnable2){
threadPool.scheduleAtFixedRate(aRunnable1,1,20, TimeUnit.MILLISECONDS);
threadPool.scheduleAtFixedRate(aRunnable2,1,20, TimeUnit.MILLISECONDS);
}
/**使用Thread執行緒測試*/
public static void testUseThread(Runnable runnable1, Runnable runnable2){
new Thread(runnable1).start();
new Thread(runnable2).start();
}
public static void testFixedThreadPool(Runnable runnable1, Runnable runnable2){
fixedThreadPool.execute(runnable1);
fixedThreadPool.execute(runnable2);
}
/**執行緒迴圈排程*/
public static class ARunnable implements Runnable {
private final static Logger LOGGER = LoggerFactory.getLogger(ARunnable.class);
String name; //執行緒名稱
int count = 0; //計數
boolean isInterrupt = false; //是否內部中斷執行緒
int interruptCount ; //count達到 interruptCount 時中斷執行緒
public ARunnable(){ }
public ARunnable(String name, boolean isInterrupt, int interruptCount){
this.name = name;
this.isInterrupt = isInterrupt;
this.interruptCount = interruptCount;
}
@Override
public void run() {
if(isInterrupt && interruptCount == count){
Thread.currentThread().interrupt();
LOGGER.warn("A interrupt ... name:"+name+",count:"+count++);
}else{
LOGGER.warn("A name:"+name+",count:"+count++);
}
}
}
/**內部迴圈執行*/
public static class BRunnable implements Runnable {
private final static Logger LOGGER = LoggerFactory.getLogger(BRunnable.class);
String name; //執行緒名稱
int count = 0; //計數
boolean isInterrupt = false; //是否內部中斷執行緒
int interruptCount ; //count達到 interruptCount 時中斷執行緒
public BRunnable(){ }
public BRunnable(String name, boolean isInterrupt, int interruptCount){
this.name = name;
this.isInterrupt = isInterrupt;
this.interruptCount = interruptCount;
}
@Override
public void run() {
while(true){
try {
Thread.sleep(20);
} catch (InterruptedException e) {
e.printStackTrace();
}
if(isInterrupt && interruptCount == count){
Thread.currentThread().interrupt();
LOGGER.warn("B interrupt ...name:"+name+",count:"+count++);
}
LOGGER.warn("B name:"+name+",count:"+count++);
}
}
}
}
測試結果
採用多種執行緒測試,兩個執行緒,對一中一個執行緒在一定條件後進行interrupt(),觀察日誌輸出檔案的輸出情況
- 以下三種情況控制檯輸出基本一致(被interrupt後仍然會繼續列印日誌),如下:
start ----
2018-08-26 21:31:08.014 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:0
2018-08-26 21:31:08.014 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:0
2018-08-26 21:31:08.044 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:1
2018-08-26 21:31:08.045 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:1
2018-08-26 21:31:08.064 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:2
2018-08-26 21:31:08.065 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:2
2018-08-26 21:31:08.084 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:3
2018-08-26 21:31:08.085 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:3
2018-08-26 21:31:08.105 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:4
2018-08-26 21:31:08.105 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:4
2018-08-26 21:31:08.125 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:5
2018-08-26 21:31:08.126 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:5
2018-08-26 21:31:08.146 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:6
2018-08-26 21:31:08.146 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:6
2018-08-26 21:31:08.166 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B interrupt ...name:b-n-2,count:7
2018-08-26 21:31:08.166 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:7
2018-08-26 21:31:08.167 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:8
2018-08-26 21:31:08.169 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:9
java.lang.InterruptedException: sleep interrupted
at java.lang.Thread.sleep(Native Method)
at com.bonree.utils.TestA$BRunnable.run(TestA.java:135)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2018-08-26 21:31:08.187 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:8
2018-08-26 21:31:08.189 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:10
2018-08-26 21:31:08.208 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:9
2018-08-26 21:31:08.209 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:11
2018-08-26 21:31:08.229 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:10
...後面還很多就不貼上了
testUseScheduledThreadPool(aRunnable1, aRunnable2);
方法測試結果如下
2018-08-26 21:34:57.436 [pool-1-thread-1] WARN com.bonree.utils.TestA$ARunnable - A name:a-n-1,count:0
2018-08-26 21:34:57.436 [pool-1-thread-2] WARN com.bonree.utils.TestA$ARunnable - A name:a-n-2,count:0
2018-08-26 21:34:57.454 [pool-1-thread-1] WARN com.bonree.utils.TestA$ARunnable - A name:a-n-1,count:1
2018-08-26 21:34:57.454 [pool-1-thread-5] WARN com.bonree.utils.TestA$ARunnable - A name:a-n-2,count:1
2018-08-26 21:34:57.474 [pool-1-thread-2] WARN com.bonree.utils.TestA$ARunnable - A name:a-n-1,count:2
2018-08-26 21:34:57.475 [pool-1-thread-3] WARN com.bonree.utils.TestA$ARunnable - A name:a-n-2,count:2
2018-08-26 21:34:57.494 [pool-1-thread-4] WARN com.bonree.utils.TestA$ARunnable - A name:a-n-1,count:3
2018-08-26 21:34:57.495 [pool-1-thread-1] WARN com.bonree.utils.TestA$ARunnable - A name:a-n-2,count:3
2018-08-26 21:34:57.514 [pool-1-thread-4] WARN com.bonree.utils.TestA$ARunnable - A name:a-n-1,count:4
2018-08-26 21:34:57.515 [pool-1-thread-2] WARN com.bonree.utils.TestA$ARunnable - A name:a-n-2,count:4
2018-08-26 21:34:57.534 [pool-1-thread-3] WARN com.bonree.utils.TestA$ARunnable - A name:a-n-1,count:5
後面就沒有了,也就是說interrupt後就不打日誌了
testUseThread(bRunnable1,bRunnable2);
方法測試結果如下
2018-08-26 21:33:53.142 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:0
2018-08-26 21:33:53.142 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:0
2018-08-26 21:33:53.178 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:1
2018-08-26 21:33:53.178 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:1
2018-08-26 21:33:53.199 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:2
2018-08-26 21:33:53.199 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:2
2018-08-26 21:33:53.219 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:3
2018-08-26 21:33:53.219 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:3
2018-08-26 21:33:53.244 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:4
2018-08-26 21:33:53.244 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:4
2018-08-26 21:33:53.264 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:5
2018-08-26 21:33:53.264 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:5
2018-08-26 21:33:53.284 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:6
2018-08-26 21:33:53.284 [pool-3-thread-2] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-2,count:6
2018-08-26 21:33:53.304 [pool-3-thread-1] WARN com.bonree.utils.TestA$BRunnable - B name:b-n-1,count:7
後面就沒有了,也就是說interrupt後就不打日誌了
testFixedThreadPool(bRunnable1,bRunnable2);
方法測試結果與testUseThread
方法測試結果一致
以上測試說明在多執行緒日誌檔案列印過程中,一旦某執行緒被interrupt後,其他執行緒都不會列印日誌了。
注:經過測試,版本提高後就不會出現該問題,日誌檔案中輸出沒有不列印的情況