业务日志内容与格式探讨

在开发日志系统，简单的日志系统用ELK即可，代码量很少。在分析日志时，发现大量日志格式存在问题，真正的工作在于日志内容的分类、日志格式的梳理。

日志级别概述

ERROR

• ERROR是最高级别错误，反映系统发生了非常严重的故障，无法自动恢复到正常态工作，需要人工介入处理。系统需要将错误相关痕迹以及错误细节记录ERROR日志中，方便后续人工回溯解决。

WARN

• WARN是低级别异常日志，反映系统在业务处理时触发了异常流程，但系统可恢复到正常态，下一次业务可以正常执行。但WARN级别问题需要开发人员给予足够关注，往往表示有参数校验问题或者程序逻辑缺陷，当功能逻辑走入异常逻辑时，应该考虑记录WARN日志。

INFO

• INFO日志主要记录系统关键信息，旨在保留系统正常工作期间关键运行指标，开发人员可以将初始化系统配置、业务状态变化信息，或者用户业务流程中的核心处理记录到INFO日志中，方便日常运维工作以及错误回溯时上下文场景复现。

DEBUG

• 开发人员可以将各类详细信息记录到DEBUG里，起到调试的作用，包括参数信息，调试细节信息，返回值信息等等。其他等级不方便显示的信息都可以通过DEBUG日志来记录

使用WARN和统计报警

由于WARN是低级别异常日志，不需要马上处理。但是如果频次过于频繁，达到一定阈值，就发出报警，进行处理。

强调ERROR报警

ERROR的报出应该伴随着业务功能受损，即上面提到的系统中发生了非常严重的问题，必须有人马上处理。

ERROR日志目标

给处理者直接准确的信息：error信息形成自身闭环。

1. 问题定位：发生了什么问题，哪些功能受到影响
2. 获取帮助信息：直接帮助信息或帮助信息的存储位置
3. 通过报警知道解决方案或者找何人解决

实用模板

日志模板2选1：

log.error(“[接口名或操作名] [Some Error Msg] happens. [Probably Because]. [Probably need to do] [params] .”);

log.error(“[接口名或操作名] [Some Error Msg] happens. [Probably Because]. [please contact xxx@xxx] [params] .”);

尽量按上述模板完成，如果实施起来有难度，至少ERROR 日志打印时需要在做一个自我问答，能非常有效的帮助评估这条报警是否有意义：这条报警看到之后我能处理吗？ 应该怎么处理? 如果是同事看到能处理或者及时通知联系人呢吗？ 因为你不可能保证随时都处在工作状态，但报警时随时有可能出现的。

日志输出内容

日志输出的注意点

我不确定大家是否遇到过下面的情况：*排查问题时，发现那块出现错误的地方有日志输出，但是输出的日志对于排查问题一点用都没有**，每当出现这种情况的时候我都想骂人。

好的日志需要有哪些内容呢？

• 发生时间
• 出现问题的线程
• 日志级别
• 出现问题的类文件，类的哪一行，异常栈
• 程序入参
• 相应的程序员的注释等

（可选项）

• 会话标识，能知道是哪个客户端或者是哪个用户触发，登陆账号，seesion信息等
• 通过RequestID来对请求进行唯一的标记，目的是可以通过RequestID将一个请求在系统中的执行过程串联起来。根据不同的目的生成RequestID，必要时在RequestID中尽量编码更多的信息

日志框架选型

新的Log4j 2.x版本有了大幅的性能提升、新的插件系统，以及配置设置方面的很多改善。Log4j 1.x 在高并发情况下出现死锁导致cpu使用率异常飙升，而Log4j2.x基于LMAX Disruptor的异步日志在多线程环境下性能会远远优于Log4j 1.x和logback。

• Log4j 2.x 日志升级的详细流程（针对各种混合使用Log4j 1.x，Logback，JCL,JUL等）

log4j2-spring.xml配置

springboot 推荐***-spring.xml的命名规范。

日志配置主要涉及2点：

1. who？ 就是谁输出日志，可指定根目录、或者具体的包路径

<Loggers>
    <Logger name="com.foo.Bar" level="trace">
      <AppenderRef ref="Console"/>
    </Logger>
    <Root level="error">
      <AppenderRef ref="Console"/>
    </Root>
  </Loggers>

2. 输出的目录与格式

<Appenders>
    <Console name="Console" target="SYSTEM_OUT">
      <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %t %-5level %C{36} %M %L %msg%xEx%n"/>
    </Console>
  </Appenders>

日志包含基本内容：

• 发生时间
• 出现问题的线程
• 日志级别
• 出现问题的类文件，类的哪一行，异常栈

循环日志文件：日志文件大于阀值的时候，就开始写一个新的日志文件

<!--
    循环日志文件：日志文件大于阀值的时候，就开始写一个新的日志文件
    这个会打印出所有的信息，每次大小超过size，则这size大小的日志会自动存入按年份-月份建立的文件夹下面并进行压缩，作为存档

    fileName    : 指定当前日志文件的位置和文件名称
    filePattern : 指定当发生Rolling时，文件的转移和重命名规则
    SizeBasedTriggeringPolicy : 指定当文件体积大于size指定的值时，触发Rolling
    DefaultRolloverStrategy : 指定最多保存的文件个数
    TimeBasedTriggeringPolicy : 这个配置需要和filePattern结合使用
        注意filePattern中配置的文件重命名规则是${FILE_NAME}_%d{yyyy-MM-dd}_%i，最小的时间粒度是dd，即天，
        TimeBasedTriggeringPolicy指定的size是1，结合起来就是每1天生成一个新文件
-->

<RollingRandomAccessFile name="INFO" fileName="logs/${FILE_NAME}.log" filePattern="log/${FILE_NAME}_%d{yyyy-MM-dd}_%i.log.gz">
    <Filters>
        <ThresholdFilter level="WARN" onMatch="DENY" onMismatch="NEUTRAL"/>
        <ThresholdFilter level="TRACE" onMatch="ACCEPT" onMismatch="DENY"/>
    </Filters>
    <PatternLayout pattern=" %d{yyyy-MM-dd HH:mm:ss.SSS} %t %-5level %C{36} %M %L %msg%xEx%n"/>
    <Policies>
        <TimeBasedTriggeringPolicy interval="1"/>
        <SizeBasedTriggeringPolicy size="1MB"/>
    </Policies>
    <DefaultRolloverStrategy max="20"/>
</RollingRandomAccessFile>

配置格式扩展

1. 自定义格式：

%t：线程名称

%p：日志级别

%c：日志消息所在类名

%m：消息内容

%M：输出执行方法

%d：发生时间，%d{yyyy-MM-dd HH:mm:ss,SSS}，输出类似：2011-10-18 22:10:28,921

%x: 输出和当前线程相关联的NDC(嵌套诊断环境),尤其用到像java servlets这样的多客户多线程的应用中。

%L：代码中的行数

%n：换行

<PatternLayout pattern="%d{HH:mm:ss.SSS} %-5level %class{36} %L %M -%msg%xEx%n"/>

2. Logger Names

package org.apache.test;
 
public class MyTest {
    private static final Logger logger = LogManager.getLogger();
}

3. 代码日志打印

With Java 8 you can achieve the same effect with a lambda expression. You no longer need to explicitly check the log level:

 Java-8 style optimization: no need to explicitly check the log level:
 the lambda expression is not evaluated if the TRACE level is not enabled
logger.trace("Some long-running operation returned {}", () -> expensiveOperation());

在java8中不用显示判断日志级别，如果未启用该日志级别，则不会执行lambda表达式。

自定义过滤器类

log4j2中用ThreadContext代替MD

public class ThreadContextFilter implements Filter {


    @Override
    public void init(FilterConfig filterConfig) throws ServletException {

    }

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        try {
            ThreadContext.put("UUID", StaticUUID.ID);    //StaticUUID是自己写的类，用于生成UUID常量。
            ThreadContext.put("ip", request.getLocalAddr());
            chain.doFilter(request, response);
        } finally {
        //清除ThreadContext,避免内存泄露
            ThreadContext.clearAll();
        }
    }

    @Override
    public void destroy() {

    }

}

这样可以在日志中动态输出一些信息，如ip,用户名等。

<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %class{1.}:%L - IP:%X{ip}&amp;ID:%X{UUID}  %msg%xEx%n" />

阿里java编程规范-日志部分：

日志规约

【强制】应用中不可直接使用日志系统（Log4j、Logback）中的API，而应依赖使用日志框架SLF4J中的API，使用门面模式的日志框架，有利于维护和各个类的日志处理方式统一。
      import org.slf4j.Logger;
      import org.slf4j.LoggerFactory;
          private static final Logger logger = LoggerFactory.getLogger(Abc.class);        
      slf4j是日志门面框架，其仅提供日志记录的API，而不实现日志记录的功能，slf4j需要通过适配库适配到log4j或logback等日志系统来实现日志的记录。使用slf4j api能够提升代码和应用的可移植性，在使用不同日志系统的应用之间能够做到无缝的适配。同时，使用slf4j api的应用，在切换日志系统时（比如从logback切换到log4j2，不需要代码改造）

【强制】日志文件推荐至少保存15天，因为有些异常具备以“周”为频次发生的特点。

【强制】应用中的扩展日志（如打点、临时监控、访问日志等）命名方式：appName_logType_logName.log。
       logType:日志类型，推荐分类有stats/desc/monitor/visit等；
       logName:日志描述。这种命名的好处：通过文件名就可知道日志文件属于什么应用，什么类型，什么目的，也有利于归类查找。
       正例：mppserver应用中单独监控时区转换异常，如： mppserver_monitor_timeZoneConvert.log
       说明：推荐对日志进行分类，如将错误日志和业务日志分开存放，便于开发人员查看，也便于通过日志对系统进行及时监控。

【强制】对trace/debug/info级别的日志输出，必须使用条件输出形式或者使用占位符的方式。
       说明：logger.debug("Processing trade with id: " + id + " symbol: " + symbol); 如果日志级别是warn，上述日志不会打印，但是会执行字符串拼接操作，如果symbol是对象，会执行toString()方法，浪费了系统资源，执行了上述操作，最终日志却没有打印。
       正例：（条件）
           if (logger.isDebugEnabled()) { 
               logger.debug("Processing trade with id: " + id + " symbol: " + symbol); 
             }      
       正例：（占位符）
           logger.debug("Processing trade with id: {} symbol : {} ", id, symbol);     
      占位符方式，log4j2/logback支持，log4j1.x是不直接支持的，只能通过slf4j库适配

【强制】避免重复打印日志，浪费磁盘空间，务必在log4j.xml中设置additivity=false。
        正例：
           additivity默认为true，即通过该logger输出的日志会同时输出到root logger，如果还为该logger指定了独立的appender，就会导致这部分日志重复输出

【强制】异常信息应该包括两类信息：案发现场信息和异常堆栈信息。如果不处理，那么通过关键字throws往上抛出。
        正例：
            logger.error(各类参数或者对象toString + "_" + e.getMessage(), e);             
      记录异常日志的常见错误：
        logger.error(e);
        logger.error(e.getMessage());
        logger.error("上下文"+e.getMessage())；        
      上面这几种都是错的！请确保使用的是两个入参的API，如error(String s, Throwable t)

【推荐】谨慎地记录日志。生产环境禁止输出debug日志；有选择地输出info日志；如果使用warn来记录刚上线时的业务行为信息，一定要注意日志输出量的问题，避免把服务器磁盘撑爆，并记得及时删除这些观察日志。
        说明：大量地输出无效日志，不利于系统性能提升，也不利于快速定位错误点。记录日志时请思考：这些日志真的有人看吗？看到这条日志你能做什么？能不能给问题排查带来好处？不要认为日志记录不怎么消耗性能，我见过不少事无巨细式的日志把系统性能严重拖慢的案例

【参考】可以使用warn日志级别来记录用户输入参数错误的情况，避免用户投诉时，无所适从。注意日志输出的级别，error级别只记录系统逻辑出错、异常等重要的错误

参考

• spring boot 各版本中使用 log4j2 记录日志
• logback layouts
• log4j2 layouts
• log4j2配置固定内容(IP等)
• log4j patten格式
• log4jtester
• Log4J2 配置文件模板及代码说明
• log4j2配置固定内容(IP等)

---

tips:本文属于自己学习和实践过程的记录，很多图和文字都粘贴自网上文章，没有注明引用请包涵！如有任何问题请留言或邮件通知，我会及时回复。