JAVA日志规范

JAVA日志规范


常见的日志级别有5种,分别是error、warn、info、debug、trace。日常开发中,我们需要选择恰当的日志级别,不要反手就是打印info

  • error:错误日志,指比较严重的错误,对正常业务有影响,需要运维配置监控的
  • warn:警告日志,一般的错误,对业务影响不大,但是需要开发关注
  • info:信息日志,记录排查问题的关键信息,如调用时间、出参入参等等;
  • debug:用于开发DEBUG的,关键逻辑里面的运行时数据;
  • trace:最详细的信息,一般这些信息只记录到日志文件中

日志级别从低到高分为TRACE < DEBUG < INFO < WARN < ERROR < FATAL,如果设置为WARN,则低于WARN的信息都不会输出

一、日志要打印出方法的入参、出参

public String testLogMethod(Document doc, Mode mode){
   if (logger.isDebugEnabled()) {
     log.debug(“method enter param:{},userId);
   }
   String id = "666";
   if (logger.isDebugEnabled()) {
     log.debug(“method exit param:{},id);
   }
   return id;
}

二、选择合适的日志格式

理想的日志格式,应当包括这些最基本的信息:如当前时间戳(一般毫秒精确度)、日志级别线程名字等等。在logback日志里可以这么配置:

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} %-5level [%thread][%logger{0}] %m%n</pattern>
    </encoder>
</appender>

<!-- 异步的方式记录日志 -->
<appender name="FILE_ASYNC" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="ASYNC"/>
</appender>

三、遇到if…else…等条件时,每个分支首行都尽量打印日志

正例:

if(user.isVip()){
  log.info("该用户是会员,Id:{},开始处理会员逻辑",user,getUserId());
  //会员逻辑
}else{
  log.info("该用户是非会员,Id:{},开始处理非会员逻辑",user,getUserId())
  //非会员逻辑
}

四、日志级别比较低时,进行日志开关判断

对于trace/debug这些比较低的日志级别,必须进行日志级别的开关判断

正例:

User user = new User(666L, "公众号", "boy");
if (log.isDebugEnabled()) {
    log.debug("userId is: {}", user.getId());
}
logger.debug("Processing trade with id: " + id + " and symbol: " + symbol);

如果配置的日志级别是warn的话,上述日志不会打印,但是会执行字符串拼接操作,如果symbol是对象, 
还会执行toString()方法,浪费了系统资源,执行了上述操作,最终日志却没有打印,因此建议加日志开关判断。

五、不能直接使用日志系统(Log4j、Logback)中的 API,而是使用日志框架SLF4J中的API

SLF4J 是门面模式的日志框架,有利于维护和各个类的日志处理方式统一,并且可以在保证不修改代码的情况下,很方便的实现底层日志框架的更换。

正例:

import org.slf4j.Logger; 
import org.slf4j.LoggerFactory;

private static final Logger logger = LoggerFactory.getLogger(TianLuoBoy.class);

六、建议使用参数占位{},而不是用+拼接

正例:

logger.info("Processing trade with id: {} and symbol : {} ", id, symbol); 

使用了大括号{}来作为日志中的占位符,比于使用+操作符,更加优雅简洁。并且,相对于反例,使用占位符仅是替换动作,可以有效提升性能

七、使用异步的方式来输出日志

  • 日志最终会输出到文件或者其它输出流中的,IO性能会有要求的。如果异步,就可以显著提升IO性能。
  • 除非有特殊要求,要不然建议使用异步的方式来输出日志。以logback为例吧,要配置异步很简单,使用AsyncAppender就行
<appender name="FILE_ASYNC" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="ASYNC"/>
</appender>


 <!-- error级别:按照每天生成日志文件 -->
    <appender name="FILEERROR"  class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_HOME}/neo4j_error.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <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>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>ERROR</level>
        </filter>
    </appender>

    <!--配置异步日志
    <appender name="STDOUT_ASYNC" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="STDOUT"/>
    </appender>
    <appender name="FILE_ASYNC" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="FILE"/>
    </appender>
    <appender name="FILEWARN_ASYNC" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="FILEWARN"/>
    </appender>-->
    <appender name="FILEERROR_ASYNC" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="FILEERROR"/>
    </appender>


    <!-- show parameters for hibernate sql 专为 Hibernate 定制 
    <logger name="org.hibernate.type.descriptor.sql.BasicBinder"  level="TRACE" />
    <logger name="org.hibernate.type.descriptor.sql.BasicExtractor"  level="DEBUG" />
    <logger name="org.hibernate.SQL" level="DEBUG" />
    <logger name="org.hibernate.engine.QueryParameters" level="DEBUG" />
    <logger name="org.hibernate.engine.query.HQLQueryPlan" level="DEBUG" />-->

    <!--myibatis task configure
    <logger name="com.apache.ibatis" level="TRACE"/>
    <logger name="java.sql.Connection" level="DEBUG"/>
    <logger name="java.sql.Statement" level="DEBUG"/>
    <logger name="java.sql.PreparedStatement" level="DEBUG"/>-->

    <!-- 日志输出级别 -->
    <root level="INFO">
        <appender-ref ref="STDOUT_ASYNC" />
        <appender-ref ref="FILE_ASYNC" />
        <appender-ref ref="FILEWARN_ASYNC"/>
        <appender-ref ref="FILEERROR_ASYNC" />
    </root>

八、不要使用e.printStackTrace(),记录日志要输出全部错误信息

正例:

try{
  // 业务代码处理
}catch(Exception e){
  // 记录日志要输出全部错误信息, 记录e
  log.error("你的程序有异常啦",e);
}
  • e.printStackTrace()打印出的堆栈日志跟业务代码日志是交错混合在一起的,通常排查异常日志不太方便。
  • e.printStackTrace()语句产生的字符串记录的是堆栈信息,如果信息太长太多,字符串常量池所在的内存块没有空间了,即内存满了,那么,用户的请求就卡住啦

九、禁止在线上环境开启 debug

因为一般系统的debug日志会很多,并且各种框架中也大量使用 debug的日志,线上开启debug不久可能会打满磁盘,影响业务系统的正常运行

十、不要记录了异常,又抛出异常

反例:

log.error("IO exception", e);
throw new MyException(e);
  • 这样实现的话,通常会把栈信息打印两次。这是因为捕获了MyException异常的地方,还会再打印一次。
  • 这样的日志记录,或者包装后再抛出去,不要同时使用!否则你的日志看起来会让人很迷惑。

如果你是使用log4j日志框架,务必在log4j.xml中设置 additivity=false,因为可以避免重复打印日志

<logger name="com.taobao.dubbo.config" additivity="false"> 

十一、日志文件分离

  • 我们可以把不同类型的日志分离出去,比如access.log,或者error级别error.log,都可以单独打印到一个文件里面。
  • 当然,也可以根据不同的业务模块,打印到不同的日志文件里,这样我们排查问题和做数据统计的时候,都会比较方便啦

logback-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<!-- 日志级别从低到高分为TRACE < DEBUG < INFO < WARN < ERROR < FATAL,如果设置为WARN,则低于WARN的信息都不会输出 -->
<!-- scan:当此属性设置为true时,配置文件如果发生改变,将会被重新加载,默认值为true -->
<!-- scanPeriod:设置监测配置文件是否有修改的时间间隔,如果没有给出时间单位,默认单位是毫秒。当scan为true时,此属性生效。默认的时间间隔为1分钟。 -->
<!-- debug:当此属性设置为true时,将打印出logback内部日志信息,实时查看logback运行状态。默认值为false。 -->
<configuration  scan="true" scanPeriod="10 seconds">
  <springProperty scope="context" name="app_name" source="spring.application.name" />
    <!--<include resource="org/springframework/boot/logging/logback/base.xml" />-->

    <contextName>logback</contextName>
    <!-- name的值是变量的名称,value的值时变量定义的值。通过定义的值会被插入到logger上下文中。定义变量后,可以使“${}”来使用变量。 -->
    <property name="log.path" value="logs/${app_name}" />

    <!-- 彩色日志 -->
    <!-- 彩色日志依赖的渲染类 -->
    <conversionRule conversionWord="clr" converterClass="org.springframework.boot.logging.logback.ColorConverter" />
    <conversionRule conversionWord="wex" converterClass="org.springframework.boot.logging.logback.WhitespaceThrowableProxyConverter" />
    <conversionRule conversionWord="wEx" converterClass="org.springframework.boot.logging.logback.ExtendedWhitespaceThrowableProxyConverter" />
    <!-- 彩色日志格式 -->
    <property name="CONSOLE_LOG_PATTERN" value="${CONSOLE_LOG_PATTERN:-%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>


    <!--输出到控制台-->
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <!--此日志appender是为开发使用,只配置最底级别,控制台输出的日志级别是大于或等于此级别的日志信息-->
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>debug</level>
        </filter>
        <encoder>
            <Pattern>${CONSOLE_LOG_PATTERN}</Pattern>
            <!-- 设置字符集 -->
            <charset>UTF-8</charset>
        </encoder>
    </appender>


    <!--输出到文件-->

    <!-- 时间滚动输出 level为 DEBUG 日志 -->
    <appender name="DEBUG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!-- 正在记录的日志文件的路径及文件名 -->
        <file>${log.path}/log_debug.log</file>
        <!--日志文件输出格式-->
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern>
            <charset>UTF-8</charset> <!-- 设置字符集 -->
        </encoder>
        <!-- 日志记录器的滚动策略,按日期,按大小记录 -->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- 日志归档 -->
            <fileNamePattern>${log.path}/debug/%d{yyyy-MM-dd}/log-debug-%d{yyyy-MM-dd}.%i.gz</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>100MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <!--日志文件保留天数-->
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <!-- 此日志文件只记录debug级别的 -->
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>debug</level>
            <!-- 匹配到就允许 -->
            <onMatch>ACCEPT</onMatch>
            <!-- 未匹配到就禁止 -->
            <onMismatch>DENY</onMismatch>
        </filter>
    </appender>

    <!-- 时间滚动输出 level为 INFO 日志 -->
    <appender name="INFO_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!-- 正在记录的日志文件的路径及文件名 -->
        <file>${log.path}/log_info.log</file>
        <!--日志文件输出格式-->
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern>
            <charset>UTF-8</charset>
        </encoder>
        <!-- 日志记录器的滚动策略,按日期,按大小记录 -->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- 每天日志归档路径以及格式 -->
            <fileNamePattern>${log.path}/info/%d{yyyy-MM-dd}/log-info-%d{yyyy-MM-dd}.%i.gz</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>100MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <!--日志文件保留天数-->
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <!-- 此日志文件只记录info级别的 -->
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>info</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
    </appender>

    <!-- 时间滚动输出 level为 WARN 日志 -->
    <appender name="WARN_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!-- 正在记录的日志文件的路径及文件名 -->
        <file>${log.path}/log_warn.log</file>
        <!--日志文件输出格式-->
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern>
            <charset>UTF-8</charset> <!-- 此处设置字符集 -->
        </encoder>
        <!-- 日志记录器的滚动策略,按日期,按大小记录 -->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${log.path}/warn/%d{yyyy-MM-dd}/log-warn-%d{yyyy-MM-dd}.%i.gz</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>100MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <!--日志文件保留天数-->
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <!-- 此日志文件只记录warn级别的 -->
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>warn</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
    </appender>


    <!-- 时间滚动输出 level为 ERROR 日志 -->
    <appender name="ERROR_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!-- 正在记录的日志文件的路径及文件名 -->
        <file>${log.path}/log_error.log</file>
        <!--日志文件输出格式-->
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern>
            <charset>UTF-8</charset> <!-- 此处设置字符集 -->
        </encoder>
        <!-- 日志记录器的滚动策略,按日期,按大小记录 -->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${log.path}/error/%d{yyyy-MM-dd}/log-error-%d{yyyy-MM-dd}.%i.gz</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>100MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <!--日志文件保留天数-->
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <!-- 此日志文件只记录ERROR级别的 -->
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>ERROR</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
    </appender>
    
    <root level="info">
        <appender-ref ref="CONSOLE" />
        <appender-ref ref="DEBUG_FILE" />
        <appender-ref ref="INFO_FILE" />
        <appender-ref ref="WARN_FILE" />
        <appender-ref ref="ERROR_FILE" />
    </root>

</configuration>

十二、日志注意事项

1 )ERROR

ERROR 级别的日志一般在 catch 块里面出现,用于记录影响当前线程正常运行的错误,出现 Exception 的地方就可以考虑打印 ERROR 日志,但不包括业务异常。

需要注意的是,如果你抛出了异常,就不要记录 ERROR 日志了应该在最终的地方处理,下面这样做就是不对的:

try {

  int i = 1 / 0;

} catch (Exception e) {

  log.error("出错了,什么错我不知道,啊哈哈哈!", e);

  throw new CloudBaseException();

}

2)WARN

不应该出现,但是不会影响当前线程执行的情况可以考虑打印 WARN 级别的日志,这种情况有很多,比如:

  • 各种池(线程池、连接池、缓存池)的使用超过阈值,达到告警线
  • 记录业务异常
  • 出现了错误,但是设计了容错机制,因此程序能正常运行,但需要记录一下

3)INFO

使用最多的日志级别,使用范围很广,用来记录系统的运行信息,比如:

  • 重要模块中的逻辑步骤呈现
  • 客户端请求参数记录
  • 调用第三方时的参数和返回结构

4)DEBUG

Debug 日志用来记录自己想知道的所有信息,常常是某个功能模块运行的详细信息,已经中间的数据变化,以及性能信息。

Debug 信息在生产环境一般是关闭状态的,需要使用开关管理(比如 SpringBoot Admin 可以做到),一直开启会产生大量的 Debug,而 Debug 日志在程序正常运行时大部分时间都没什么用。

if (log.isDebugEnabled()) {

  log.debug("开始执行,开始时间:[{}],参数:[{}]", startTime, params);

  log.debug("通过计算,得到参数1:[{}],参数2:[{}]", param1, param2);

  log.debug("最后处理结果:[{}]", result);

}

5)TRACE

特别详细的系统运行完成信息,业务代码中一般不使用,除非有特殊的意义,不然一般用 DEBUG 代替,事实上,我编码到现在,也没有用过这个级别的日志。

使用正确的格式

如果你是这样打印日志的:

log.info("根据条件id:{}" + id + "查询用户信息");

不要这样做,会产生大量的字符串对象,占用空间的同时也会影响性能。

正确的做法是使用参数化信息的方式:

log.info("根据条件id:[{}],查询用户信息", id);

这样做除了能避免大量创建字符串之外,还能明确的把参数隔离出去,当你需要把参数复制出来的时候,只需要双击鼠标即可,而不是用鼠标慢慢对准再划拉一下。

这样打出来的日志,可读性强,对排查问题的帮助也很大!

小技巧

1)多线程

遇到多个线程一起执行的日志怎么打?

有些系统,涉及到并发执行,定时调度等等,就会出现多次执行的日志混在一起,出问题不好排查,我们可以把线程名打印进去,或者加一个标识用来表明这条日志属于哪一次执行:

if (log.isDebugEnabled()) {

  log.debug("执行ID=[{}],处理了ID=[{}]的消息,处理结果:[{}]", execId, id, result);

}

MDC日志追踪

MDC介绍
1、简介:

MDC(Mapped Diagnostic Context,映射调试上下文)是 log4j 、logback及log4j2 提供的一种方便在多线程条件下记录日志的功能。MDC 可以看成是一个与当前线程绑定的哈希表,可以往其中添加键值对。MDC 中包含的内容可以被同一线程中执行的代码所访问。

2、一般时候,我们为了日志追踪,会在日志中拼接参数,代码具有侵入性,也容易忘记。MDC结合log4j,程序会在适当时候当我们拼接好参数。

MDC使用
1.拦截器中使用MDC put 键值对。使得所有请求,从一开始就标记上特定标识。
2.如果是微服务之间的调用,则需要上层服务在header中添加标识同请求一起传输过来。下层服务直接使用上层服务的标识,就可以将日志串联起来。

public class LogInterceptor implements HandlerInterceptor {

  @Override

  public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {

    //如果有上层调用就用上层的ID

    String traceId = request.getHeader(Constants.TRACE_ID);

    if (traceId == null) {

      traceId = UUID.randomUUID().toString();

    }

    MDC.put(Constants.TRACE_ID, traceId);

    return true;

  }

  @Override

  public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {

    MDC.clear();

  }

}

重点:修改logback日志格式

<property name="pattern">[TRACEID:%X{traceId}] %d{HH:mm:ss.SSS} %-5level %class{-1}.%M()/%L - %msg%xEx%n</property>

也可以只在配置文件中添加配置

logging.pattern.console="%d %.-1p traceId:[%X{traceId}] --- [%t] %logger{16} : %replace(%m%wEx){'[\r\n]+', '\t'}%nopex%n"

MDC的坑

1.主线程中,如果使用了线程池,会导致线程池中丢失MDC信息;
解决办法:需要我们自己重写线程池,在调用线程跳动run之前,获取到主线程的MDC信息,重新put到子线程中的。

public class MDCLogThreadPoolExecutor extends ThreadPoolExecutor {

  public MDCLogThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit, BlockingQueue<Runnable> workQueue) {

    super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);

  }

  @Override

  public void execute(Runnable command) {

    super.execute(MDCLogThreadPoolExecutor.executeRunable(command, MDC.getCopyOfContextMap()));

  }

  @Override

  public Future<?> submit(Runnable task) {

    return super.submit(MDCLogThreadPoolExecutor.executeRunable(task, MDC.getCopyOfContextMap()));

  }

  @Override

  public <T> Future<T> submit(Callable<T> callable) {

    return super.submit(MDCLogThreadPoolExecutor.submitCallable(callable,MDC.getCopyOfContextMap()));

  }

  public static Runnable executeRunable(Runnable runnable ,Map<String,String> mdcContext){

    return new Runnable() {

      @Override

      public void run() {

        if (mdcContext == null) {

          MDC.clear();

        } else {

          MDC.setContextMap(mdcContext);

        }

        try {

          runnable.run();

        } finally {

          MDC.clear();

        }

      }

    };

  }

  private static <T> Callable<T> submitCallable( Callable<T> callable,  Map<String, String> context) {

    return () -> {

      if (context == null) {

        MDC.clear();

      } else {

        MDC.setContextMap(context);

      }

      try {

        return callable.call();

      } finally {

        MDC.clear();

      }

    };

  }

}

评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值