logback使用规约

1. 本文档目的

帮助不熟悉Logback的同学，合理配置、使用Logback，提升日志打印性能，降低冗余日志的打印；
规范各项目的日志打印；
$\color{red}{坚持：合理正确的打印日志属于日常开发工作的一部分；}$

2. Logback 生产配置文件推荐

$\color{red}{不同环境的日志打包，各系统 Owner 根据系统情况使用 Maven实现。}$

2.1 生产环境日志配置

用在测试、灰度、线上环境；
采用异步 appender 提升性能；
error 和 dubbo 日志单独打印；

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="false" debug="false">
    <!-- 配置文件中可以被引用的属性，value 值推荐通过 maven 打包时替换 -->
    <property name="LOG_HOME" value="${log.sys.path}"/>
    <property name="LOG_LEVEL" value="${log.sys.level}"/>
 
    <!-- 根日志：这个文件是全部所有的日志内容 -->
    <appender name="rootAllFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>${LOG_HOME}/root.%d{yyyy-MM-dd}.%i.log</FileNamePattern>
            <maxHistory>30</maxHistory>
            <totalSizeCap>500GB</totalSizeCap>
            <!-- 按时间回滚的同时，按文件大小来回滚 -->
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>1GB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
        </rollingPolicy>
        <encoder>
            <pattern>
                [%level] [%thread] [%d{yyyy-MM-dd HH:mm:ss.SSS}] [%mdc{traceid}] [%mdc{jdb_traceid}] [%logger{0}] [%msg]%n
            </pattern>
        </encoder>
    </appender>
 
    <!-- error 日志单独输出，上线重点关注这个文件的日志 -->
    <appender name="errorFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>${LOG_HOME}/error.%d{yyyy-MM-dd}.%i.log</FileNamePattern>
            <maxHistory>30</maxHistory>
            <totalSizeCap>500GB</totalSizeCap>
            <!-- 按时间回滚的同时，按文件大小来回滚 -->
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>1GB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
        </rollingPolicy>
 
        <encoder>
            <pattern>
                [%level] [%thread] [%d{yyyy-MM-dd HH:mm:ss.SSS}] [%mdc{traceid}] [%mdc{jdb_traceid}] [%logger] [%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="alarmFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>${LOG_HOME}/monitor/alarm.%d{yyyy-MM-dd}.log</FileNamePattern>
            <maxHistory>30</maxHistory>
            <totalSizeCap>50GB</totalSizeCap>
        </rollingPolicy>
        <encoder>
            <pattern>
                [%d{yyyy-MM-dd HH:mm:ss.SSS}] [%mdc{traceid}] [%msg]%n
            </pattern>
        </encoder>
    </appender>
 
    <!-- dubbo 日志，要多注意，某个服务出现问题 dubbo 框架日志会打印到这里，如超时 -->
    <appender name="rpcFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>${LOG_HOME}/rpc.%d{yyyy-MM-dd}.log</FileNamePattern>
            <maxHistory>30</maxHistory>
            <totalSizeCap>50GB</totalSizeCap>
        </rollingPolicy>
        <encoder>
            <pattern>
                [%level] [%thread] [%mdc{traceid}] [%d{yyyy-MM-dd HH:mm:ss.SSS}] [%logger] [%msg]%n
            </pattern>
        </encoder>
    </appender>
 
    <!-- 用来提升异步性能的appender -->
    <!--<appender name="asyncRootAppender" class="ch.qos.logback.classic.AsyncAppender">-->
        <!--&lt;!&ndash; 不丢弃日志，最大长度设置为 2048 &ndash;&gt;-->
        <!--<discardingThreshold>0</discardingThreshold>-->
        <!--<queueSize>2048</queueSize>-->
        <!--<appender-ref ref="rootAllFile"/>-->
    <!--</appender>-->
 
    <!-- 注意 additivity 决定了是否累加 appender -->
    <logger name="rpc-event" level="WARN" additivity="false">
        <appender-ref ref="rpcFile"/>
    </logger>
 
    <logger name="com.jiupai.pay.commons.log.monitor.MonitorLog">
        <appender-ref ref="alarmFile"/>
    </logger>
 
    <root level="${LOG_LEVEL}">
        <!-- 异步 appender 性能提升的同时有一些问题需要注意 -->
        <!-- 如果不能接受这些问题，改为 rootAllFile 通过减少日志等方式提升性能 -->
        <!--<appender-ref ref="asyncRootAppender"/>-->
        <appender-ref ref="rootAllFile"/>
        <appender-ref ref="errorFile"/>
    </root>
</configuration>

2.2 开发环境的日志配置

用在本地做调试的日志配置；
为避免冲突把变量放到 local-ip.properties 中比较合适；

<?xml version="1.0" encoding="UTF-8"?>
<!-- 每分钟自动扫描下配置变化，并且打印 logback 内部的日志信息 -->
<configuration scan="true" debug="${log.logback.debug}">
    <!-- 打印到控制台的标准输出，WEB 环境下就是输出到 catalina.out 文件中 -->
    <appender name="stdoutAppender" class="ch.qos.logback.core.ConsoleAppender">
        <target>System.out</target>
        <encoder>
            <pattern>[%p][%d{yyyy-MM-dd HH:mm:ss}][%X{traceid}][%X{user_name}][%X{interface}][%c %L][%m]%n</pattern>
        </encoder>
    </appender>
 
    <root level="${log.sys.level}">
        <appender-ref ref="stdoutAppender"/>
    </root>
</configuration>

3.日志打印规约

日志打印应遵循如下原则：

避免打印冗余日志：同样的日志输出多次，类似信息输出多次；
避免打印不易查询和统计的日志：RD 应善于利用 AWK、SED、CUT、WC 等函数，打印的日志应利于日志的分析、统计、查询：
避免打印“无效”的日志：日志的目的是方便 RD 观察、分析程序运行情况，不利于此目的的日志应避免打印或优化输出：
$\color{red}{1.【强制】保证合理配置：开发时禁止修改生产环境适用的 logback 配置文件；}$
本地开发调试时使用开发的 logback 配置；
将 logback 的日志级别放到 pom 或属性文件中，由 Maven 根据环境打包；
禁止将生产日志设置为 DEBUG 或修改其配置；
$\color{red}{2.【强制】保证 logger 有合理的继承结构：获取 Logger 时必须使用 SLF4J API ：}$ LoggerFactory.getLogger(Class clazz) ；
仅依赖 SLF4J API，不要依赖 Commons-Logging API；
getLogger时仅传递类名字；
正例：Logger logger = LoggerFactory.getLogger(UserService.class);
反例：Logger logger = LoggerFactory.getLogger("userService");

$\color{red}{3.【强制】保证合理日志 Level：告警级别日志采用 Warn 级别，错误必须用 Error，}$
$\color{red}{留痕等业务日志采用 Info，调试日志必须使用： logger.debug(String format, Object... arguments)；}$
$\color{red}{合理使用 Logger 的API，不混用日志级别；}$
非正常流程的日志如 catch 块、不期望的兼容处理：使用 Warn 及以上级别打印方法；
正常流程作为程序诊断参考，留痕参考，证明程序正确性的日志：使用 Info 级别，并尽量使用 logger.info(String format, Object... arguments) 这个方法重载；
异常日志要打印异常栈，注意打印异常栈，提示消息的格式化不能依赖 Logback ，使用 logger.error(String msg, Throwable t) 重载方法：
DEBUG 日志尽量使用 logger.debug(String format, Object... arguments) ；
正例：

try{
    logger.debug("|UserUpdate|更新用户信息|userInfo = [{}]",userInfo);
    int x = userDao.update(userInfo);
    if(x != 1){
      logger.warn("|UserUpdate|用户信息未更新成功,做兼容处理|x = [{}]",x);
     // 兼容更新失败逻辑
     .....
      
    }
    logger.info("|UserUpdate|用户信息更新完成|userInfo = [{}]|",userInfo);
}catch(Exception e){
    logger.error("|UserUpdate|用户信息更新失败|msg = [" + e.getMessage() + "]|", e);
}

反例：

try{
    // 和正确的版本比，有30倍的性能差，尽量不要这么用。
    logger.debug("|UserUpdate|更新用户信息|userInfo = [{" + userInfo + "}]");
    int x = userDao.update(userInfo);
    if(x != 1){
      // 异常不期望日志，应该是 warn 或者 error
      logger.info("|UserUpdate|用户信息未更新成功,做兼容处理|x = [{" + x + "}]");
     // 兼容更新失败逻辑
     .....
      
    }
    // 正常期望日志，不要用 warn
    logger.wan("|UserUpdate|用户信息更新完成|userInfo = [{}]|",userInfo);
}catch(Exception e){
    // 这个 API 无法打印出异常栈
    logger.error("|UserUpdate|用户信息更新失败|msg = [{}]|", e.getMessage ,e);
}

$\color{red}{4.【推荐】使用有模式的日志输出，方便未来做日志统计和分析，维持一套中/英文日志约定；}$
$\color{red}{项目成员约定：日志输出模式，模式应该方便被 awk、sed、cut 等liunx 字符串处理命令处理；}$
$\color{red}{所有的日志模式不论级别应该维持恒定；}$
给每类日志添加一个可方便统计的 key 串（推荐英文）；
项目成员约定：日志提示信息采用中文还是英文并维持一套；
变量输出推荐：使用中括号包裹，包裹时不加空格，方便区分变量输出的是空格、空串、null串；
正例：

logger.info("|EnterpRegCtrl|引擎处理开始|enterpInfo = [{}]|",enterpInfo);
int engineRs = doInvokeEngine(enterpInfo);
String engineMsg = getEngineMsg(engineRs);
logger.info("|EnterpRegCtrl|引擎结束|engineRs = [{}]|engineMsg = [{}]|",engineRs,engineMsg);

反例：

logger.info("risk engine begin process",enterpInfo);
int engineRs = doInvokeEngine(enterpInfo);
String engineMsg = getEngineMsg(engineRs);
logger.info("引擎结束 , engineMsg : {} , engineRs = {}",engineRs,engineMsg);

$\color{red}{5. 【强制】无统一升级指令，不自主升级更换日志框架及版本}$
维持当前项目 logback 版本，无统一升级指令，不升级；
当前部分代码直接依赖了 logback 的API，升级可能导致奇怪问题。

4. Linux 下的日志分析

4.1 常用分析命令

日志查询和浏览命令

tail：查询日志文件末尾日志，常用参数
-f / -xxf ：循环读取，用来监控日志；
grep：查询符合条件的日志
-A [N] : 显示符合条件的日志及后面 N 行日志；
-B [N] : 显示符合条件的日志及前面 N 行日志；
-C [n] : 显示符合条件的日志及前后 N 行日志；
-v [msg] : 排查掉符合条件的日志不显示；
cat：查看日志全部内容
-n / -b : 显示行号
日志分割和统计命令：
awk：强大的日志分析工具，三两句话无法解释；
-F ：指定分割符；
cut：按行切分日志；
-d -f ：指定切分符，-d 和 -f ；
wc：统计文本字符数和行数
-l : 统计一共有多少行；

以上命令的参数大小写敏感，仅列出常用参数和选项，更多的还是需要系统性自学和应用。

4.2 查询并过滤日志

查询符合条件的日志

基于 traceId 的查询，推荐： grep -A 可以显示错误栈；
基于自己的日志 key 的查询，推荐先统计行数再显示；
例子

## 知道符合条件的日志不多，如有异常5行可以显示
grep -A 5 "<日志ID>" 文件
 
 
## 看下符合条件的行数，如果太多不要直接显示了
grep -A 10 "<关键字>" 文件 | wc -l
 
 
## 修改关键字或排除一些内容看行数
grep -A 10 "<关键字>" 文件 | grep -v "<要排除的日志>" | wc -l
 
 
## 观察关系的日志
tail -f 文件 | grep -C 10  "<关键字>"

4.3 统计某类日志

使用 wc -l 做简单行数统计；
使用 awk 做复杂的统计；

## 统计类日志出现次数，先确认下统计内容
grep "<关键字>" 文件 | head -n 10
## 统计出现次数
grep "<关键字>" 文件 | wc -l
 
 
## 对某日志中变量做累加统计，
## 每行的日志模式：[%level] [%thread] [%d{yyyy-MM-dd HH:mm:ss.SSS}] [%mdc{traceid}] [%mdc{jdb_traceid}] [%msg]%n
## %msg 的格式为 |MQConsumer|ReceiveSuccess|ifSuccess = [true]|Key = [T_PAYRISK_URC_5f800c4ddad84ab4a939ed54dd5389c3]|
## 1. 先找打符合条件的日志
## 2. 按照固定模式分割，以中括号切分，%msg 是第14列
## 3. 按照竖线切分，可以打印或统计 ifSuccess 的次数，下面是打印
awk -F '[\]\[\]' '{print $14}' a.log | awk -F '|' '{print $4}'

4.4 按照行来定位日志

常用来查询异常，知道发生了异常，然后看具体异常栈

## 找到符合条件的日志和行号
cat -n <文件名称> | grep "<关键字>"
 
 
## 记下行号，假设上面的行发生在 m 行， 那么显示 m 的前后50行日志
cat -n <文件名> | tail +<m-50> | head -n 100

5. 需要了解的一些基本知识点

Logback 官网有200多页文档，对 Logback 有很全面的介绍，推荐阅读：

5.1 Appender 的累加性和 Logger 的继承

Logback 的 Appender 表示日志的输出方向，每一个 appender 表示输出到一个文件、控制台等，每一个 logger 可以有 0 到多个 Appender。
Appender 是累加的，Logger 是有继承关系的，使用类名作为 logger 的 name，logger 就有很明显的继承层次。如以 com.jiupai.pay 命名的 logger 是所有以此前缀为 name 的 logger 的 parent。
所有 logger 都有 root logger 就是配置文件的 root 节点代表的 logger。 logger 会从 parent 继承 appender 并做累计。如 root logger 有一个 appender 写入到 console。
这个时候再指定 com.jiupai.pay 这个 logger 的 appender 到一个文件，则每条 com.jiupai.pay logger 都会分别写入到 console 和 file 中，日志会重复输出两次。
每个 logger 可以有多个 appender ，如 root logger 指定两个 appender : file 和 console ，则每条日志都会写入到两次。
因此，配置 logback 时一定要注意是否需要指定多个 appender ，以及每个 logger 实际会有几个 appender。

5.2 异步 Appender 的潜在问题

一般的 Appender 是同步写入的，并且默认每一次 logger.info("需要写入的日志信息"); 调用都会发生一次 IO 操作，对于本地文件的写入，一般耗时在 30 微秒左右。

logback 的 AsyncAppender 实际上就是创建了一个 BlockingQueue ，当日志写入请求（log event）到来时，将这个请求 push 到 BlockingQueue 中。

因此 AsyncAppender 的异步会有如下几个问题：

如果需要打印的日志含有一些复杂对象，并且这个对象在接下来可能会变，那么打印的日志信息可能不准确：
如果未正确关闭程序，logback 框架无法正常停止，则可能会丢失掉还在 BlockingQueue 的日志，导致日志输出可能不全；
如果日志量过大，BlockingQueue 的长度过大，内存占用会很高，甚至会丢掉无法 push 到队列中的日志，甚至性能下降。

public void doRegister(User user){
 // 使用异步 appender ，如果量很大，则这条日志很可能被丢掉；
 logger.info("|UserRegister|用户注册|user = [{}]|",user);
 // …… 做一些处理
 user.setUserID("123");
 // 再次输出 信息，则第一次打印的 userId 可能也是 123；
 // 如果程序这个时候被kill 了，则这个条日志还可能不会输出;
 logger.info(""|UserRegister|更新用户信息|user = [{}]|",user");
}

5.3 何时选择 AsyncAppender

AsyncAppender 有一些配置可以部分解决上述 4.2 提到的异步 Appender 的潜在问题，但是这些配置应该结合业务情况决定是否使用（否则 logback 肯定会把 AsyncAppender 作为首选推荐）。
压测是参考非唯一标准
压测 QPS/TPS 上去了，但是某些压测无法观察出上出异步 Appender 的问题；
考虑业务日志是否绝大部分都是输出了基本类型变量
基本类型变量，Logback 做异步任务的时候是做了数据提取的（includeCallerData）,这个时候可以少考虑日志输出数据不准确的潜在问题；
考虑业务系统停机是否优雅
如果业务系统集成各种框架不需要粗暴的 kill -9 操作，停机时丢失日志的风险不大；
考虑业务系统是否容忍上述日志问题
上述问题，大部分系统是可以接受的，且发生概率较小；
如果非常担心上述问题，可以考虑为业务系统提供一个同步 logger ，部分场景需要同步打印可以使用同步 logger 打印日志。
异常日志不推荐异步输出
首先，异常不是系统经常发生的，压测时也一样，如果经常需要打印，那需要考虑换一种代码实现或日志打印级别（如warn）
其次，异常应和告警应及时 flush 到硬盘，方便问题查询；

6. 选择其他日志框架

6.1 面向门面编程

程序代码要严格遵守：面向门面 SLF4J 的 API 编程，即使使用代码来初始化日志框架，也应该尽量遵循面向接口编程原则，不要直接依赖日志框架 API。

6.2 Log4J

不推荐了，logback 明确是作为 log4j 的继任者，重新了很多组件，性能更高，没理由使用 log4j。

6.3 Log4J 2

具官网介绍，从原理分析，和部分实测，Log4J 2 的性能确实别 logback 高，但是 log4j 2 原理要比 logback 复杂，实际应用稳定性未知。