logbackログがファイルに印刷されない問題の詳細分析
logbackがファイルにログを印刷しない問題の分析とケーススタディを詳しく探究し、公式サイトのbugの提出リンクを提供する.環境と構成 問題 解決 理由 テストソース 試験結果 深さ:スレッドに異常が発生してもログ が印刷されるかどうか
環境と構成
mavenを使用して構築されたlogback依存は、次のように導入されます.(注:他の依存は、他のログ・フレームワークの依存を排除しているため、ログ・フレームワークの競合問題はありません.これもポイントですよ)
に質問オンラインシステムの問題を1回チェックするとlogbackにログが出力されない場合があり、有効なログチェックで問題が発生しないことがわかります. は実際にログ出力があることを発見しますが、いくつかのログは出力できません.大きな方向から見ると、ログに が漏れています. logbackもフィルタログを構成していない場合を考えると 资料を调べて、各ブログのウェブサイトはすべて関连する実例がなくて、まだないいくつかの类似の问题はすべて私の环境と异なって、だから彼らの情况を排除します 解決する
まずソリューションについてお話ししましょう.
次はバグについてお話ししましょう
の原因となる
prudentプロパティをtrueに設定したFileAppenderスレッドがinterruptされると、その後のログは印刷されません.
これはlogback公式サイト1.3のリリース時に解決されたバグです.バグをコミットした原作者の説明バグは以下の通りです.
簡単に理解すると、スレッドが中断されると、後続のログは他のスレッドも含めて印刷されません.再現例も示されており、その説明ページを参照して設計しましたが、確かにそうです.転送ゲート:logback 1.1.3リリース解決バグ:LOGBACK-875 個人提供例 節
テストソース
複数のスレッドテスト、2つのスレッドを採用し、1つのスレッドに対して一定の条件の後にinterrupt()を行い、ログ出力ファイルの出力状況を観察する.
テスト結果
複数のスレッドテスト、2つのスレッドを採用し、1つのスレッドに対して一定の条件の後にinterrupt()を行い、ログ出力ファイルの出力状況を観察する.以下の3つの場合、コンソール出力はほぼ一致します(interrupt後もログの印刷が続行されます). である. である. である.
以上のテストでは、マルチスレッドログファイルの印刷中に、あるスレッドがinterruptされると、他のスレッドはログを印刷しません.
注意:テストの結果、バージョンがアップするとこの問題は発生しません.ログファイルの出力に印刷されない場合はありません.
詳細:スレッドに異常が発生してもログが印刷されるかどうか
ここでのテストスキームは
次の質問に答えることができます.エラー後、スレッドの後にログが印刷されるかどうか(いいえ) エラー後、他のスレッドがログを印刷するかどうか スレッドプールを使用して、他のタスクを実行して を印刷するかどうか(できます)異常をキャプチャすると、スレッドは 印刷を継続するかどうか.
问题や不适切な表现があれば、伝言を残して指摘してください.ありがとうございます!!
環境と構成
mavenを使用して構築されたlogback依存は、次のように導入されます.(注:他の依存は、他のログ・フレームワークの依存を排除しているため、ログ・フレームワークの競合問題はありません.これもポイントですよ)
<dependency>
<groupId>ch.qos.logbackgroupId>
<artifactId>logback-classicartifactId>
<version>1.1.2version>
dependency>logback.xmlは以下のように構成されています:(以下は実際のオンライン環境の構成ですよ、機密情報をTESTに変更しました)
<configuration debug="false">
<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>truePrudent>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<FileNamePattern>${log.base}TEST_ERROR-%d{yyyy-MM-dd}.logFileNamePattern>
<MaxHistory>5MaxHistory>
rollingPolicy>
<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>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>ERRORlevel>
<onMatch>ACCEPTonMatch>
<onMismatch>DENYonMismatch>
filter>
appender>
<appender name="WARNFILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<Prudent>truePrudent>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<FileNamePattern>${log.base}TEST_WARN-%d{yyyy-MM-dd}.logFileNamePattern>
<MaxHistory>5MaxHistory>
rollingPolicy>
<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>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>WARNlevel>
<onMatch>ACCEPTonMatch>
<onMismatch>DENYonMismatch>
filter>
appender>
<appender name="INFOFILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<Prudent>truePrudent>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<FileNamePattern>${log.base}TEST_INFO-%d{yyyy-MM-dd}.logFileNamePattern>
<MaxHistory>5MaxHistory>
rollingPolicy>
<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>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>INFOlevel>
<onMatch>ACCEPTonMatch>
<onMismatch>DENYonMismatch>
filter>
appender>
<appender name="DEBUGFILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<Prudent>truePrudent>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<FileNamePattern>${log.base}TEST_DEBUG-%d{yyyy-MM-dd}.logFileNamePattern>
<MaxHistory>5MaxHistory>
rollingPolicy>
<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>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>DEBUGlevel>
<onMatch>ACCEPTonMatch>
<onMismatch>DENYonMismatch>
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>に質問
まずソリューションについてお話ししましょう.
1.1.2バージョンのlogbackにバグがあり、ログが出力されません.のソリューションはバージョンを向上させることです次はバグについてお話ししましょう
の原因となる
prudentプロパティをtrueに設定したFileAppenderスレッドがinterruptされると、その後のログは印刷されません.
これはlogback公式サイト1.3のリリース時に解決されたバグです.バグをコミットした原作者の説明バグは以下の通りです.
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.
簡単に理解すると、スレッドが中断されると、後続のログは他のスレッドも含めて印刷されません.再現例も示されており、その説明ページを参照して設計しましたが、確かにそうです.
テストソース
複数のスレッドテスト、2つのスレッドを採用し、1つのスレッドに対して一定の条件の後にinterrupt()を行い、ログ出力ファイルの出力状況を観察する.
【 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++);
}
}
}
}
テスト結果
複数のスレッドテスト、2つのスレッドを採用し、1つのスレッドに対して一定の条件の後に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されると、他のスレッドはログを印刷しません.
注意:テストの結果、バージョンがアップするとこの問題は発生しません.ログファイルの出力に印刷されない場合はありません.
詳細:スレッドに異常が発生してもログが印刷されるかどうか
ここでのテストスキームは
String a = null;
a.split(" ");
Thread.currentThread().interrupt();
次の質問に答えることができます.
问题や不适切な表现があれば、伝言を残して指摘してください.ありがとうございます!!