Java日志规范最佳实践

一、日志介绍

1.1 日志是什么

日志：记录程序的运行轨迹，方便查找关键信息，也方便快速定位解决问题。

日志的作用就是在测试、生产环境没有 Debug 调试工具时开发和测试人员定位问题的手段。好的日志，可以根据日志的轨迹快速定位并解决线上问题，反之，不好的日志，不仅无法辅助定位问题反而可能会影响到程序的运行性能和稳定性。

通常,我们认为日志就像写作一样应该包含 5W1H :

每条日志对应服务中就是一个事件,我们可以将每个事件拆分成各个组成部分,而拆分的维度就很重要,其中 5W1H 对事件拆分帮助很大,从某种意义上来说我们可以的参考这些维度去拆分日志和规范化日志,在此基础上建立属于我们企业自己的日志规范。

  • 日志事件:
    • Who
      用户(id)(设备id)...
    • When
      时间戳(时间节点,用于阶段化做溯源工作)
    • Where
      位置、环境、场景(ip、国家、pod、分支、运行环境...)
    • What
      是什么(问题是什么?接口是什么?方法是什么?参数是什么?异常是什么?)
    • Why
      原因是什么(产生异常的原因是什么?)
    • How
      维度特征(调用正常?调用中断?调用失败?)

1.2 日志的作用

不管是使用何种编程语言，日志输出几乎无处不再。总结起来，日志大致有以下几种用途：

  • 问题追踪： 辅助排查和定位线上问题，优化程序运行性能。
  • 状态监控： 通过日志分析，可以监控系统的运行状态。
  • 安全审计： 审计主要体现在安全上，可以发现非授权的操作。

因此,根据日志的用途大致可以将日志分为以下几种类型:

  • 监控日志
  • 统计日志
  • 访问日志
  • 行为日志
  • ...

二、日志框架

2.1 主流框架介绍

2.1.1 Logging

这是 Java 自带的日志工具类，在 JDK 1.5 开始就已经有了，在 java.util.logging 包下。通常情况下，这个基本没什么人用了，了解一下就行。

2.1.2 commons-logging

commons-logging 是日志的门面接口，它也是Apache 最早提供的日志门面接口，用户可以根据喜好选择不同的日志实现框架，而不必改动日志定义，这就是日志门面的好处，符合面对接口抽象编程。现在已经不太流行了，了解一下就行。

2.1.3 Slf4j

slf4j,英文全称为“Simple Logging Facade for Java”，为java提供的简单日志Facade。Facade门面，更底层一点说就是接口。它允许用户以自己的喜好，在工程中通过slf4j接入不同的日志系统。

因此slf4j入口就是众多接口的集合，它不负责具体的日志实现，只在编译时负责寻找合适的日志系统进行绑定。具体有哪些接口，全部都定义在slf4j-api中。查看slf4j-api源码就可以发现，里面除了public final class LoggerFactory类之外，都是接口定义。因此slf4j-api本质就是一个接口定义。

2.1.4 Log4j

Log4j 是 Apache 的一个开源日志框架，也是市场占有率最多的一个框架。

注意：log4j 在 2015-08-05 这一天被 Apache 宣布停止维护了，用户需要切换到 Log4j2上面去。

2.1.5 Log4j2

Log4j 2 Apache Log4j 2是apache开发的一款Log4j的升级产品。

Log4j2与Log4j1发生了很大的变化，log4j2不兼容log4j1。

2.1.6 Logback

Logback中文文档

Logback 是 Slf4j 的原生实现框架，同样也是出自 Log4j 一个人之手，但拥有比 log4j 更多的优点、特性和更做强的性能，现在基本都用来代替 log4j 成为主流。

Logback相对于log4j拥有更快的执行速度。基于我们先前在log4j上的工作，logback 重写了内部的实现，在某些特定的场景上面，甚至可以比之前的速度快上10倍。在保证logback的组件更加快速的同时，同时所需的内存更加少。

总结:

commons-logging、slf4j 只是一种日志抽象门面，不是具体的日志框架。

log4j、logback 是具体的日志实现框架。

在比较关注性能的地方，选择Logback或自己实现高性能Logging API可能更合适。推荐：slf4j + logback.
在已经使用了Log4j的项目中，如果没有发现问题，继续使用可能是更合适的方式：推荐组合为：slf4j + log4j2.
如果不想有依赖则使用java.util.logging或框架容器已经提供的日志接口。

2.2 LUNZ#-Java落地应用介绍

2.2.1 Slf4j

根据 2.1 中 Java 日志框架的介绍, LUNZ#-Java 日志框架选用 slf4j + logback ,集成方式:

  • 在 pom 文件中引入以下依赖:
 <dependency>
    <groupId>org.projectlombok</groupId>
    <artifactId>lombok</artifactId>
    <version>1.18.12</version>
</dependency>

如果未引入 spring-boot-starter-web ,则需要引入如下依赖;如已经引入spring-boot-starter-web,则无需添加:

<dependency>
      <groupId>ch.qos.logback</groupId>
      <artifactId>logback-classic</artifactId>
      <version>1.2.3</version>
      <scope>compile</scope>
    </dependency>
    <dependency>
      <groupId>org.apache.logging.log4j</groupId>
      <artifactId>log4j-to-slf4j</artifactId>
      <version>2.13.3</version>
      <scope>compile</scope>
    </dependency>
    <dependency>
      <groupId>org.slf4j</groupId>
      <artifactId>jul-to-slf4j</artifactId>
      <version>1.7.30</version>
      <scope>compile</scope>
</dependency>
  • 在类名上添加 @Slf4j 注解开启日志
package com.lunz.log;

import lombok.extern.slf4j.Slf4j;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;

/**
 * @Description: 日志应用启动类
 * @Author: dev_tct
 * @CreateDate: 2021/1/18
 * @Version: 1.0
 */
@Slf4j
@SpringBootApplication
public class LogApplication {
    public static void main(String[] args) {
        log.info("application is [{}],get ready to start!",LogApplication.class);
        SpringApplication.run(LogApplication.class, args);
        log.info("application is [{}],already startup!",LogApplication.class);
    }
}

三、格式规范

3.1 日志级别介绍

日志的输出都是分级别的，不同的设置不同的场合打印不同的日志。

主要使用如下的四个级别：

  • DEBUG：DEUBG 级别的主要输出调试性质的内容，该级别日志主要用于在开发、测试阶段输出。该级别的日志应尽可能地详尽，开发人员可以将各类详细信息记录到 DEBUG 里，起到调试的作用，包括参数信息，调试细节信息，返回值信息等等，便于在开发、测试阶段出现问题或者异常时，对其进行分析。

  • INFO：INFO 级别的主要记录系统关键信息，旨在保留系统正常工作期间关键运行指标，开发人员可以将初始化系统配置、业务状态变化信息，或者用户业务流程中的核心处理记录到INFO日志中，方便日常运维工作以及错误回溯时上下文场景复现。建议在项目完成后，在测试环境将日志级别调成 INFO，然后通过 INFO 级别的信息看看是否能了解这个应用的运用情况，如果出现问题后是否这些日志能否提供有用的排查问题的信息。

  • WARN：WARN 级别的主要输出警告性质的内容，这些内容是可以预知且是有规划的，比如，某个方法入参为空或者该参数的值不满足运行该方法的条件时。在 WARN 级别的时应输出较为详尽的信息，以便于事后对日志进行分析。

  • ERROR：ERROR 级别主要针对于一些不可预知的信息，诸如：错误、异常等，比如，在 catch 块中抓获的网络通信、数据库连接等异常，若异常对系统的整个流程影响不大，可以使用 WARN 级别日志输出。在输出 ERROR 级别的日志时，尽量多地输出方法入参数、方法执行过程中产生的对象等数据，在带有错误、异常对象的数据时，需要将该对象一并输出。

3.1.1 DEBUG / INFO 的选择

DEBUG 级别比 INFO 低，包含调试时更详细的了解系统运行状态的东西，比如变量的值等等，都可以输出到 DEBUG 日志里。INFO 是在线日志默认的输出级别，反馈系统的当前状态给最终用户看的。输出的信息，应该对最终用户具有实际意义的。从功能角度上说，INFO 输出的信息可以看作是软件产品的一部分，所以需要谨慎对待，不可随便输出。如果这条日志会被频繁打印或者大部分时间对于纠错起不到作用，就应当考虑下调为 DEBUG 级别。

  • 由于 DEBUG 日志打印量远大于 INFO，出于前文日志性能的考虑，如果代码为核心代码，执行频率非常高，务必推敲日志设计是否合理，是否需要下调为 DEBUG 级别日志。
  • 注意日志的可读性，不妨在写完代码 review 这条日志是否通顺，能否提供真正有意义的信息。
  • 日志输出是多线程公用的，如果有另外一个线程正在输出日志，上面的记录就会被打断，最终显示输出和预想的就会不一致。
  • 如果是业务之间边界日志，或者调用链日志，可以使用INFO级别输出，如果在K8S上则不要存储到日志文件中，建议打印到控制台上，方便日志服务采集。
3.1.2 WARN / ERROR 的选择

当方法或者功能处理过程中产生不符合预期结果或者有框架报错时可以考虑使用，常见问题处理方法包括：

  • 增加判断处理逻辑，尝试本地解决：增加逻辑判断吞掉报警永远是最优选择抛出异常，交给上层逻辑解决
  • 抛出异常，交给上层逻辑解决
  • 记录日志，报警提醒
  • 使用返回码包装错误做返回

一般来说，WARN 级别不会短信报警，ERROR 级别则会短信报警甚至电话报警，ERROR 级别的日志意味着系统中发生了非常严重的问题，必须有人马上处理，比如数据库不可用，系统的关键业务流程走不下去等等。错误的使用反而带来严重的后果，不区分问题的重要程度，只要有问题就error记录下来，其实这样是非常不负责任的，因为对于成熟的系统，都会有一套完整的报错机制，那这个错误信息什么时候需要发出来，很多都是依据单位时间内 ERROR 日志的数量来确定的。

3.1.3 强调ERROR报警
  • ERROR 级别的日志打印通常伴随报警通知。ERROR的报出应该伴随着业务功能受损，即上面提到的系统中发生了非常严重的问题，必须有人马上处理。
    ERROR日志目标:

给处理者直接准确的信息：ERROR 信息形成自身闭环。
问题定位：

  • 发生了什么问题，哪些功能受到影响

  • 获取帮助信息：直接帮助信息或帮助信息的存储位置

  • 通过报警知道解决方案或者找何人解决

3.1.4 输出条件规范

在这里插入图片描述

3.2 日志格式介绍

参考格式:

%d{yyyy-MM-dd HH:mm:ss.SSS}|${appName}|{env}|%-5level|%thread|[%C:%M:%L]| - %msg%n

  • logback.xml 示例:
<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="false">

    <springProperty scope="context" name="appName" source="spring.application.name" defaultValue="appName"/>
    <!--定义日志文件的存储地址 勿在 LogBack 的配置中使用相对路径-->
    <property name="LOG_HOME" value="/home"/>
    <!-- 控制台输出 -->
    <appender name="STDOUT-dev" class="ch.qos.logback.core.ConsoleAppender">
        <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>-->
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS}|${appName}|dev|%-5level|%thread|[%C:%M:%L]| - %msg%n</pattern>
        </encoder>
    </appender>

    <appender name="STDOUT-pro" class="ch.qos.logback.core.ConsoleAppender">
        <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>-->
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS}|%-4relative|${appName}|pro|%-5level|%thread|[%C:%M:%L]| - %msg%n
            </pattern>
        </encoder>
    </appender>
    <!-- 按照每天生成日志文件 -->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!--日志文件输出的文件名-->
            <FileNamePattern>${LOG_HOME}/${appName}.log.%d{yyyy-MM-dd}.log</FileNamePattern>
            <!--日志文件保留天数-->
            <MaxHistory>30</MaxHistory>
        </rollingPolicy>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <!-- 日志输出格式：%d 表示日期时间，%thread 表示线程名，%-5level：级别从左显示 5 个字符宽度 %logger{50} 表示 logger 名字最长 50 个字符，否则按照句点分割。%msg：日志消息，%n 是换行符 -->
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS}|${appName}|%-5level|%thread|[%C:%M:%L]| - %msg%n</pattern>
        </encoder>
        <!--日志文件最大的大小-->
        <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
            <MaxFileSize>10MB</MaxFileSize>
        </triggeringPolicy>
    </appender>
    <!-- 日志输出级别 -->
    <springProfile name="dev">
        <root level="debug">
            <appender-ref ref="STDOUT-dev"/>
        </root>
    </springProfile>


    <springProfile name="pro">
        <root level="info">
            <appender-ref ref="STDOUT-pro"/>
        </root>
    </springProfile>

</configuration>
3.2.1 对内微服务案例
%d{yyyy-MM-dd HH:mm:ss.SSS}|${appName}|pro|%-5level|%thread|[%C:%M:%L]| - %msg%n
日志时间戳|应用名称|运行环境|日志级别|线程名称|[类全限定名称:调用方法名:运行行数]| - 日志内容(换行符)
3.2.2 对内网关案例
%d{yyyy-MM-dd HH:mm:ss.SSS}|${appName}|pro|${ip}|{$url}|${spendTime}|%-5level|%thread|[%C:%M:%L]| - %msg%n
日志时间戳|应用名称|运行环境|IP地址|请求URI|接口耗时|日志级别|线程名称|[类全限定名称:调用方法名:运行行数]| - 日志内容(换行符)
3.2.3 对外微服务案例
%d{yyyy-MM-dd HH:mm:ss.SSS}|${appName}|pro|${ip}|{$url}|${spendTime}|%-5level|%thread|[%C:%M:%L]| - %msg%n
日志时间戳|应用名称|运行环境|IP地址|请求URI|接口耗时|日志级别|线程名称|[类全限定名称:调用方法名:运行行数]| - 日志内容(换行符)
3.2.4 对外网关案例
%d{yyyy-MM-dd HH:mm:ss.SSS}|${appName}|pro|%-5level|%thread|[%C:%M:%L]| - %msg%n
日志时间戳|应用名称|运行环境|日志级别|线程名称|[类全限定名称:调用方法名:运行行数]| - 日志内容(换行符)
3.2.5 多线程场景案例
%d{yyyy-MM-dd HH:mm:ss.SSS}|${appName}|pro|%-5level|%thread|[%C:%M:%L]| - %msg%n

四、注意事项

4.1 常见的日志使用规范

4.1.1 严格禁止
  1. 输出Exceptions的全部Throwable信息。因为log.error(msg)和log.error(msg,e.getMessage())这样的日志输出方法会丢失掉最重要的StackTrace信息。
void foo(){
    try{
       //do somehing 
    }catch(Exception e){
        log.error(e.getMessage());//错误示范
        log.erroe("Bad Things",e.getMessage());//错误示范
        log.error("Bad Things",e);//正确演示
    }
}
  1. 不允许记录日志后又抛出异常。如捕获异常后又抛出了自定义业务异常，此时无需记录错误日志，由最终捕获方进行异常处理。不能又抛出异常，又打印错误日志，不然会造成重复输出日志。
void foo() throws LogException{
    try{
        //do somehing 
    }catch(Exception e){
        log.error("Bad Things",e);//正确
        throw new LogException("Bad Things",e);
    }
}
  1. 不允许使用标准输出
    包括 System.out.println() 和 System.error.println() 语句。因为这个只会打印到控制台，而不会记录到日志文件中，不方便管理日志。此外，标准输出不会显示类名和行号信息，一旦代码中大量出现标准输出的代码，且日志中打印有标准输出的内容，很难定位日志内容和日志打印的位置，根本无法排查问题，想删除无用日志输出也改不动。
void foo(){
    try{
       //do somehing 
    }catch(Exception e){
        Syste.out.println(e.getMessage());//错误
        System.error.println(e.getMessage());//错误
        log.error("Bad Things",e);//正确
    }
}
  1. 不允许出现 printStackTrace
void foo(){
    try{
       //do somehing 
    }catch(Exception e){
        e.printStacktrace();//错误
        log.error("Bad Things",e);//正确
    }
}

printStackTrace 源码:

public void printStackTrace() {
    printStackTrace(System.err);
}

它其实也是利用 System.err 输出到了控制台。

  1. 禁止在线上环境开启debug级别日志输出

出于日志性能的考虑，如果代码为核心代码，执行频率非常高，则输出日志建议增加判断，尤其是低级别的输出<debug、info、warn>。

一是因为项目本身 debug 日志太多，二是各种框架中也大量使用 debug 的日志，线上开启 debug 不久就会打满磁盘，影响业务系统的正常运行。

  1. 尽量不要在循环中打印日志,尤其是不要在大循环中打印日志

如果你的框架使用了性能不高的 Log4j 框架，那就不要在上千个 for 循环中打印日志，这样可能会拖垮你的应用程序，如果你的程序响应时间变慢，那要考虑是不是日志打印的过多了。

for(int i=0; i<2000; i++){
    log.info("XX");
}

最好的办法是在循环中记录要点，在循环外面总结打印出来。

  1. 打印日志必须使用参数化信息的方式,字符拼接不仅可读性差,而且消耗性能:
log.debug("Processing trade with id: " + id + " symbol: " + symbol);  //错误
log.debug("Processing trade with id:[{}] and symbol : [{}] ", id, symbol);  //正确
  1. 并不是所有的service都进行出入口打点记录,单一、简单service是没有意义的
反例(不要这么做):
public List listByBaseType(Integer baseTypeId) {
    log.info("开始查询基地");
    BaseExample ex=new BaseExample();
    BaseExample.Criteria ctr = ex.createCriteria();
    ctr.andIsDeleteEqualTo(IsDelete.USE.getValue());
    Optionals.doIfPresent(baseTypeId, ctr::andBaseTypeIdEqualTo);
    log.info("查询基地结束");
    return baseRepository.selectByExample(ex);
}

而在负责的业务中分步骤记录日志是必须的,我们可以很清晰的获取当前业务代码执行到什么阶段,有助于我们进行问题排查和线上调优.

  1. 不要在线上输出涉及敏感信息日志,例如手机号,密码,身份证号等信息,如果必须输出,使用脱敏工具进行处理后再输出

  2. 打印有意义的日志

通常情况下在程序日志里记录一些比较有意义的状态数据：程序启动，退出的时间点；程序运行消耗时间；耗时程序的执行进度；重要变量的状态变化。

  1. 尽量使用英文表达日志信息,适配各种情况下的编码异常问题

  2. 输出日志优先是结果先行

五、意见和建议

5.1 建议

  • 在K8S上的服务，在输出日志的时候，尽量使用IO标准输出，而不是记录到日志文件中，因为打印到控制台上，阿里云SLS日志服务会采集到日志服务中，而在日志文件中则因为Pod销毁而丢失。
5.1.1 输出日志
  • 尽量使用英文表达日志信息,适配各种情况下的编码异常问题
  • 输出日志优先级是结果先行
posted @ 2024-04-08 08:53  Alex_Tann  阅读(315)  评论(0)  编辑  收藏  举报