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){// 记录日志要输出全部错误信息, 记录elog.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 {@Overridepublic boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {//如果有上层调用就用上层的IDString traceId = request.getHeader(Constants.TRACE_ID);if (traceId == null) {traceId = UUID.randomUUID().toString();}MDC.put(Constants.TRACE_ID, traceId);return true;}@Overridepublic 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);}@Overridepublic void execute(Runnable command) {super.execute(MDCLogThreadPoolExecutor.executeRunable(command, MDC.getCopyOfContextMap()));}@Overridepublic Future<?> submit(Runnable task) {return super.submit(MDCLogThreadPoolExecutor.executeRunable(task, MDC.getCopyOfContextMap()));}@Overridepublic <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() {@Overridepublic 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();}};}}