java logback异常日志没有打印 logback日志突然就不打印了

转载

mob64ca13fb1f2e 2023-10-17 09:24:34

文章标签 logback logback日志不打印日志遗漏日志丢失 log 文章分类 Java 后端开发

详细探究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.

简单理解就是线程被中断后，后面的日志都不会打印，包括其他线程。并且也给出了复现案例，我参照它的描述页设计了一下，确实如此。

传送门：logback1.1.3版本发布解决bug： LOGBACK-875
个人提供例子如下节

测试源码

采用多种线程测试，两个线程，对一中一个线程在一定条件后进行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后，其他线程都不会打印日志了。

注：经过测试，版本提高后就不会出现该问题，日志文件中输出没有不打印的情况

深入：线程出异常是否还会打印日志

这里测试方案为

String a = null;
                    a.split(" ");

                    替代

                    Thread.currentThread().interrupt();

                    来测试

可回答如下问题