Logback的深度使用经验和最佳实践
2016年05月08日


首先,日志的记录方案,在另一篇文章中单独说明:

http://blog.zollty.com/b/archive/plan-for-java-project-log.html

在该文章中,说明了Logback的下面5个功能:

1、使用logback的环境变量定义和读取功能;

2、在logback启动之前,继承ch.qos.logback.core.status.OnConsoleStatusListener,初始化变量的值;

3、使用logback的 if-then 条件语法;

4、使用<property file="xxx" />和<property resource="xxx" />加载key-value配置

5、使用<include resource="xxx"/>切分配置文件再引入。


其他基础的用法,比如 定时扫描配置,日志文件压缩,异步打印日志等功能,见下面的配置及注释:

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="60 seconds" debug="false">
  
  <statusListener class="cn.zollty.commons.logbackext.InitConfigOnConsoleStatusListener" />
  
  <!-- 部署的环境类型:dev、test、product -->
  <property name="DEPLOY_ENV" value="${deploy.env:-dev}" />
  
  <!-- 日志路径,这里是相对路径,web项目eclipse下会输出到当前目录./logs/下,如果部署到linux上的tomcat下,会输出到tomcat/logs/目录 下 -->
  <property name="LOG_HOME" value="${catalina.base:-.}/logs" />
    
  <!-- 日志文件大小,超过这个大小将被压缩 -->
  <property name="LOG_MAX_SIZE" value="100MB" />
  <!-- 日志输出格式 -->
  <property name="LOG_COMMON_PATTERN" value="%d{HH:mm:ss.SSS} [%thread] [%level] %logger - %msg%n" />
  <property name="LOG_DEV_PATTERN" value="%d{HH:mm:ss.SSS} [%thread] %-5level %logger{48}:%line - %msg%n" />
  
  <!-- 主日志级别 -->
  <property name="ROOT_LEVEL" value="${log.root.level:-DEBUG}" />
  
  <!-- APP 日志级别 -->
  <property name="APP_LEVEL" value="${log.app.level:-TRACE}" />
  <!-- APP Package 前缀: cn.cstonline.zollty -->
  <property name="APP_PACKAGE" value="cn.zollty.lightning" />
    
  <include resource="includedConfig.xml"/>
    
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>${LOG_DEV_PATTERN}</pattern>
    </encoder>
  </appender>
    
  <appender name="FILTER-DATA" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${LOG_HOME}/filter.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>${LOG_HOME}/filter/filter-%d{yyyy-MM-dd}-%i.log.zip</fileNamePattern>
      <maxHistory>90</maxHistory>
      <TimeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
        <MaxFileSize>100MB</MaxFileSize>
      </TimeBasedFileNamingAndTriggeringPolicy>
    </rollingPolicy>
    <encoder>
      <pattern>${LOG_COMMON_PATTERN}</pattern>
    </encoder>
  </appender>
    
  <appender name="ASYNC1" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="FILTER-DATA" />
  </appender>
    
  <include resource="special_log_level.xml"/>
  
  <logger name="${APP_PACKAGE}" level="${APP_LEVEL}" />
    
  <logger name="FILTER-LOGGER" level="${APP_LEVEL}" additivity="false">
    <appender-ref ref="ASYNC1" />
  </logger>
  
  <root level="${ROOT_LEVEL}">
    <!-- Required: exception log -->
    <appender-ref ref="FILE_EXCEPTION"/>
    <!-- Required: app log  -->
    <appender-ref ref="FILE_APP"/>
      
    <!-- Optional: show all debug or trace info -->
    <!-- <appender-ref ref="FILE_DEBUG"/> -->
    <!-- <appender-ref ref="FILE_TRACE"/> -->
      
    <if condition='p("DEPLOY_ENV").contains("dev")'>
      <then>
        <appender-ref ref="STDOUT" />
      </then>
    </if>
      
  </root>
  
</configuration>



Logback关闭appender方案

官方提供了shutdownHook配置:

<configurationdebug="true">
   <!-- in the absence of the class attribute, assume 
   ch.qos.logback.core.hook.DelayingShutdownHook -->
   <shutdownHook/>
  .... 
</configuration>

也可以自己定义shutdownHook的class,继承ch.qos.logback.core.hook.ShutdownHookBase,实现run方法即可。

比如:

public class MyShutdownHook extends ShutdownHookBase {

    @Override

    public void run() {

        // do something....

        super.stop();

    }

}

这样即可停止自定义的appender。(注意run方法调用super.stop()即可)


官方文档说明如下:https://logback.qos.ch/manual/configuration.html#stopContext

参见我用橙色标注的部分:

In order to release the resources used by logback-classic, it is always a good idea to stop the logback context. Stopping the context will close all appenders attached to loggers defined by the context and stop any active threads in an orderly way. Please also read the section on "shutdown hooks" just below.

import org.sflf4j.LoggerFactory;
import ch.qos.logback.classic.LoggerContext;
...

// assume SLF4J is bound to logback-classic in the current environment
LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
loggerContext.stop();

In web-applications the above code could be invoked from within the contextDestroyed method of ServletContextListener in order to stop logback-classic and release resources. Starting with version 1.1.10, the appropriate ServletContextListener is installed automatically for you (see just below).

Stopping logback-classic via a shutdown hook

Installing a JVM shutdown hook is a convenient way for shutting down logback and releasing associated resources.

<configuration debug="true">
   
<!-- in the absence of the class attribute, assume
   ch.qos.logback.core.hook.DefaultShutdownHook -->

   
<shutdownHook/>
  ....
</configuration>

Note that you may install a shutdown hook of your own making by setting the classattribute to correspond to your shutdown hook's class name.

The default shutdown hook, namely DefaultShutdownHook, will stop the logback context after a specified delay (0 by default). Stopping the context will allow up to 30 seconds for any log file compression tasks running in the background to finish. In standalone Java applications, adding a <shutdownHook/> directive to your configuration file is an easy way to ensure that any ongoing compression tasks are allowed to finish before JVM exit. In applications within a Web server, webShutdownHook will be installed automatically making <shutdownHook/> directive quite redundant and unnecessary.

WebShutdownHook or stopping logback-classic in web-applications

SINCE 1.1.10 Logback-classic will automatically ask the web-server to install a LogbackServletContainerInitializer implementing the ServletContainerInitializer interface (available in servlet-api 3.x and later). This initializer will in turn install and instance of LogbackServletContextListener. This listener will stop the current logback-classic context when the web-app is stopped or reloaded.


如果有多个Appender需要(顺序)关闭,可以参考如下方法:

import ch.qos.logback.core.Appender;
import ch.qos.logback.core.Context;
import ch.qos.logback.core.hook.ShutdownHookBase;
 
public final class APPLogbackShutdownHookManager extends ShutdownHookBase {
     
    private List<Class <? extends Appender>> shutableAppenders;
     
    public APPLogbackShutdownHookManager() {
        shutableAppenders = new ArrayList<Class <? extends Appender>>();
         
    // 在此处添加需要shutdown的appender
        shutableAppenders.add(MyXXXAppender.class);
    }
 
    @Override
    public void run() {
        this.stop(context);
 
        super.stop();
         
        // 手动强行停止Logback(最好等应用完全停止后再调用,比如当spring容器销毁后再执行)
        //LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
        //loggerContext.stop();
    }
 
    public void stop(Context context) {
        for(Class <? extends Appender> cls: shutableAppenders) {
            Appender ka = (Appender) context.getObject(cls.getName());
            if (ka != null)
                ka.stop();
        }
    }
 
}

然后配置:<shutdownHook class="com.zollty.common.APPLogbackShutdownHookManager"/> 即可。


Appender关闭不了的问题 解决方法


在Appender中的stop方法,无法被调用,

查看Logback源码,可知原因是Appender没有被注册到Context中,解决方法如下:

在自定义的Appender的start()方法末尾增加注册该appender的逻辑:

@Override
public void start() {
        super.start();
        
        …………
        
        // 在末尾加上则两行,将appender注册到Context里面
        getContext().register(this);
        getContext().putObject(this.getClass().getName(), this);
}


下面给出一个自定义Appender的完整实现:

功能:将log的数据放在appender里面缓存,定时处理日志数据(比如保存到数据库或者发送给日志收集服务器)

代码如下:

import java.util.Calendar;
import java.util.Date;
import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.ThreadFactory;
import java.util.concurrent.TimeUnit;
 
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.UnsynchronizedAppenderBase;
 
/**
 * 定时推送数据<br>
 * 
 * 可以实现 {@link #handleLog(String)} 方法处理简单日志内容。 <br>
 * 也可以重载 {@link #append(ILoggingEvent)} 方法处理复杂日志内容。
 * 
 * @author zollty
 * @since 2016-9-3
 */
public abstract class TimingAppender extends UnsynchronizedAppenderBase<ILoggingEvent> {
     
    private ScheduledExecutorService scheduledExecutorService;
 
    private long delay;
 
    /**
     * 处理日志内容
     * @param log 日志内容
     */
    protected abstract void handleLog(String log);
 
    protected abstract Runnable getRunnable();
 
    @Override
    protected void append(ILoggingEvent event) {
        handleLog(event.getFormattedMessage());
    }
 
    @Override
    public void start() {
        super.start();
        scheduledExecutorService = Executors.newSingleThreadScheduledExecutor(new ThreadFactory() {
            @Override
            public Thread newThread(Runnable r) {
                Thread t = new Thread(r);
                t.setName("TimingAppenderScheduledThread");
                return t;
            }
        });
        long initialDelay = delay == 60000 ? calcDelayTime() : 1000;
        System.out.println(String.format("ScheduledExecutorService start to run. initialDelay=%dms, delay=%dms", initialDelay, delay));
        scheduledExecutorService.scheduleWithFixedDelay(getRunnable(), initialDelay, delay, TimeUnit.MILLISECONDS);
         
        getContext().register(this);
        getContext().putObject(this.getClass().getName(), this);
    }
 
    public void setDelay(String delay) {
        this.delay = Long.valueOf(delay);
    }
 
    /**
     * 获取距当前时间的下一分钟的毫秒数,例如 当前时间(15:21 32S),那么return (15:22 00S) - (15:21 32S) = 28000MS
     */
    private static long calcDelayTime() {
        Date d1 = new Date();
        Calendar calendar = Calendar.getInstance();
        calendar.setTime(d1);
        calendar.set(calendar.get(1), calendar.get(2), calendar.get(5), calendar.get(11), calendar.get(12), 60);
        return calendar.getTime().getTime() - d1.getTime();
    }
     
    @Override
    public void stop() {
      if (!isStarted())
        return;
 
      // mark this appender as stopped so that Worker can also processPriorToRemoval if it is invoking aii.appendLoopOnAppenders
      // and sub-appenders consume the interruption
      super.stop();
 
      scheduledExecutorService.shutdown();
      System.out.println("ScheduledExecutorService is stopped.");
    }
}