乱打日志的兄弟技术怎么样我不知道，但是加班肯定很多!
前言
线上出现问题，你的第一反应是什么？
如果是我的话，第一时间想的应该是查日志：
- if…else 到底进入了哪个分支？
- 关键参数是不是有缺失？
- 入参是不是有问题，没做好校验放进去了？
良好的日志能帮我们快速定位到问题所在，坑你的东西往往最为无形，良好的日志就是要让这些玩意无所遁形！
日志级别
Java应用中，日志一般分为以下5个级别：
- ERROR 错误信息
- WARN 警告信息
- INFO 一般信息
- DEBUG 调试信息
- TRACE 跟踪信息
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);
}
复制代码2）使用 SpringBoot Admin 灵活开关日志级别
日志打印的15个好建议
1. 选择恰当的日志级别
常见的日志级别有5种，分别是error、warn、info、debug、trace。日常开发中，我们需要选择恰当的日志级别，不要反手就是打印info哈~
- error：错误日志，指比较严重的错误，对正常业务有影响，需要运维配置监控的；
- warn：警告日志，一般的错误，对业务影响不大，但是需要开发关注；
- info：信息日志，记录排查问题的关键信息，如调用时间、出参入参等等；
- debug：用于开发DEBUG的，关键逻辑里面的运行时数据；
- trace：最详细的信息，一般这些信息只记录到日志文件中。
2. 日志要打印出方法的入参、出参
我们并不需要打印很多很多日志，只需要打印可以快速定位问题的有效日志。有效的日志，是甩锅的利器！
哪些算得的上有效关键的日志呢？比如说，方法进来的时候，打印入参。再然后呢，在方法返回的时候，就是打印出参，返回值。入参的话，一般就是userId或者bizSeq这些关键信息。正例如下：
public String testLogMethod(Document doc, Mode mode){ log.debug(“method enter param：{}”,userId); String id = "666"; log.debug(“method exit param：{}”,id); return id;}3. 选择合适的日志格式
理想的日志格式，应当包括这些最基本的信息：如当前时间戳（一般毫秒精确度）、日志级别，线程名字等等。在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> 如果我们的日志格式，连当前时间都沒有记录，那连请求的时间点都不知道了？
4. 遇到if...else...等条件时，每个分支首行都尽量打印日志
当你碰到if...else...或者switch这样的条件时，可以在分支的首行就打印日志，这样排查问题时，就可以通过日志，确定进入了哪个分支，代码逻辑更清晰，也更方便排查问题了。
正例：
if(user.isVip()){ log.info("该用户是会员,Id:{},开始处理会员逻辑",user,getUserId()); //会员逻辑}else{ log.info("该用户是非会员,Id:{},开始处理非会员逻辑",user,getUserId()) //非会员逻辑}5.日志级别比较低时，进行日志开关判断
对于trace/debug这些比较低的日志级别，必须进行日志级别的开关判断。
正例：
User user = new User(666L, "公众号", "捡田螺的小男孩");if (log.isDebugEnabled()) { log.debug("userId is: {}", user.getId());}因为当前有如下的日志代码：
logger.debug("Processing trade with id: " + id + " and symbol: " + symbol);如果配置的日志级别是warn的话，上述日志不会打印，但是会执行字符串拼接操作，如果symbol是对象， 还会执行toString()方法，浪费了系统资源，执行了上述操作，最终日志却没有打印，因此建议加日志开关判断。
6. 不能直接使用日志系统（Log4j、Logback）中的 API，而是使用日志框架SLF4J中的API。
SLF4J 是门面模式的日志框架，有利于维护和各个类的日志处理方式统一，并且可以在保证不修改代码的情况下，很方便的实现底层日志框架的更换。
正例：
import org.slf4j.Logger; import org.slf4j.LoggerFactory;private static final Logger logger = LoggerFactory.getLogger(TianLuoBoy.class);7. 建议使用参数占位{}，而不是用+拼接。
反例：
logger.info("Processing trade with id: " + id + " and symbol: " + symbol);上面的例子中，使用+操作符进行字符串的拼接，有一定的性能损耗。
正例如下：
logger.info("Processing trade with id: {} and symbol : {} ", id, symbol); 我们使用了大括号{}来作为日志中的占位符，比于使用+操作符，更加优雅简洁。并且，相对于反例，使用占位符仅是替换动作，可以有效提升性能。
8. 建议使用异步的方式来输出日志。
- 日志最终会输出到文件或者其它输出流中的，IO性能会有要求的。如果异步，就可以显著提升IO性能。
- 除非有特殊要求，要不然建议使用异步的方式来输出日志。以logback为例吧，要配置异步很简单，使用AsyncAppender就行
<appender name="FILE_ASYNC" class="ch.qos.logback.classic.AsyncAppender"> <appender-ref ref="ASYNC"/></appender>9. 不要使用e.printStackTrace()
反例：
try{ // 业务代码处理}catch(Exception e){ e.printStackTrace();}正例：
try{ // 业务代码处理}catch(Exception e){ log.error("你的程序有异常啦",e);}理由：
- e.printStackTrace()打印出的堆栈日志跟业务代码日志是交错混合在一起的，通常排查异常日志不太方便。
- e.printStackTrace()语句产生的字符串记录的是堆栈信息，如果信息太长太多，字符串常量池所在的内存块没有空间了,即内存满了，那么，用户的请求就卡住啦~
10. 异常日志不要只打一半，要输出全部错误信息
反例1：
try { //业务代码处理} catch (Exception e) { // 错误 LOG.error('你的程序有异常啦');} - 异常e都没有打印出来，所以压根不知道出了什么类型的异常。
反例2：
try { //业务代码处理} catch (Exception e) { // 错误 LOG.error('你的程序有异常啦', e.getMessage());} - e.getMessage()不会记录详细的堆栈异常信息，只会记录错误基本描述信息，不利于排查问题。
正例：
try { //业务代码处理} catch (Exception e) { // 错误 LOG.error('你的程序有异常啦', e);} 11. 禁止在线上环境开启 debug
禁止在线上环境开启debug，这一点非常重要。
因为一般系统的debug日志会很多，并且各种框架中也大量使用 debug的日志，线上开启debug不久可能会打满磁盘，影响业务系统的正常运行。
12.不要记录了异常，又抛出异常
反例如下：
log.error("IO exception", e);throw new MyException(e);- 这样实现的话，通常会把栈信息打印两次。这是因为捕获了MyException异常的地方，还会再打印一次。
- 这样的日志记录，或者包装后再抛出去，不要同时使用！否则你的日志看起来会让人很迷惑。
13.避免重复打印日志
避免重复打印日志，酱紫会浪费磁盘空间。如果你已经有一行日志清楚表达了意思，避免再冗余打印，反例如下：
if(user.isVip()){ log.info("该用户是会员,Id:{}",user,getUserId()); //冗余，可以跟前面的日志合并一起 log.info("开始处理会员逻辑,id:{}",user,getUserId()); //会员逻辑}else{ //非会员逻辑}如果你是使用log4j日志框架，务必在log4j.xml中设置 additivity=false，因为可以避免重复打印日志
正例：
<logger name="com.taobao.dubbo.config" additivity="false"> 14.日志文件分离
- 我们可以把不同类型的日志分离出去，比如access.log，或者error级别error.log，都可以单独打印到一个文件里面。
- 当然，也可以根据不同的业务模块，打印到不同的日志文件里，这样我们排查问题和做数据统计的时候，都会比较方便啦。
15. 核心功能模块，建议打印较完整的日志
- 我们日常开发中，如果核心或者逻辑复杂的代码，建议添加详细的注释，以及较详细的日志。
- 日志要多详细呢？脑洞一下，如果你的核心程序哪一步出错了，通过日志可以定位到，那就可以啦。
微服务分布式架构中，如何实现日志链路跟踪
Logback 配置案例
日志级别排序为： TRACE < DEBUG < INFO < WARN < ERROR
- %d：表示日期
- %n：换行
- %thread：表示线程名
- %level：日志级别
- %msg：日志消息
- %file：表示文件名
- %class： 表示文件名
- %logger：Java类名（含包名，这里设定了36位，若超过36位，包名会精简为类似a.b.c.JavaBean)
- %line：Java类的行号
注意：
%-4relative %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread][%X{TRACE_ID}] %-5level %logger{100}.%M\(%line\) - %msg%n在logback中,％relative表示自应用程序启动以来打印相对时间戳(以毫秒为单位). ％-4只是元素的对齐方式.
案例
3452487 2021-08-03 15:19:36.940 [thread-monitor-daemon][] WARN com.xxxx.common.util.MonitorLogger.warn(27) - 发现超时线程notify-replay-consumer...由于案例中是守护线程thread-monitor-daemon，所以不记录链路ID。
对在系统设计的时候对于线程的命名规范也是有约束的
这里就不做详细展开后续有机会会分享。
回归正题比如下面的例子中记录了请求的链路ID
19006989 2021-08-04 22:35:25.776 [http-nio-0.0.0.0-8010-exec-10][1fc8pebmgwukw863w2p342rp2936a3r157w0:0:] INFO com.xxx.framework.eureka.core.listener.EurekaStateChangeListener.listen(58) - 服务实例[XX-PAAS]注册成功,当前服务器已注册服务实例数量[3]对于上图中显示的系统启动时间、当前时间、当前线程、对应路径按照logback官方配置就可以逐步完善对于的日志信息，但是对于链路ID的生成写入就需要特殊处理。
链路ID设计
对于链路追踪设计我个人比较喜欢两种方案
第一种
在每一次请求中链路编号（traceId）、单元编号（spanId）都是通过HttpHeader的方式进行传递，日志的起始位置会主动生成traceId、spanId，而起始位置的Parent SpanId则是不存在的，值为null。
这样每次通过restTemplate、Openfeign的形式访问其他服务的接口时，就会携带起始位置生成的traceId、spanId到下一个服务单元。
第二种
在每一次请求中链路编号（traceId），没经过一次微服务对于深度(Deep)加1
public static class ThreadTraceListener implements ThreadListener {
@Override
public void onThreadBegin(HttpServletRequest request) {
String traceToken = ThreadLocalUtil.getTranVar(TRACE_ID);
String fromServer = ThreadLocalUtil.getTranVar(FROM_SERVER);
int deep;
String traceId;
if (StringUtils.isBlank(traceToken)) {
traceId = IDGenerator.generateID();
deep = 0;
traceToken = StringHelper.join(traceId, ":0");
} else {
int index = traceToken.lastIndexOf(':');
traceId = traceToken.substring(0, index);
deep = Integer.valueOf(traceToken.substring(index + 1));
}
ThreadLocalUtil.setLocalVar(TRACE_ID, traceId);
ThreadLocalUtil.setLocalVar(TRACE_DEEP, deep);
ThreadLocalUtil.setTranVar(TRACE_ID, StringHelper.join(traceId, ":", deep + 1));
ThreadLocalUtil.setLocalVar(FROM_SERVER, fromServer);
ThreadLocalUtil.setTranVar(FROM_SERVER, getCurrentServer());
MDC.put(TRACE_ID, StringHelper.join(traceToken, ":", fromServer));
}
@Override
public void onThreadEnd(HttpServletRequest request) {
MDC.remove(TRACE_ID);
}
}请求拦截
protected void doFilterInternal(HttpServletRequest request,
HttpServletResponse response,
FilterChain chain) throws ServletException, IOException {
long startTime = System.currentTimeMillis();
// 从Header中装载传递过来的变量
Map<String, Object> tranVar = new HashMap<String, Object>();
Enumeration<String> headers = request.getHeaderNames();
while (headers.hasMoreElements()) {
String key = headers.nextElement();
if (!StringUtils.isEmpty(key)
&& key.startsWith(ThreadLocalUtil.TRAN_PREFIX)) {
tranVar.put(key.substring(ThreadLocalUtil.TRAN_PREFIX.length()),
request.getHeader(key));
}
}
ThreadLocalHolder.begin(tranVar, request);
try {
if (isGateway) {
response.addHeader("X-TRACE-ID", TraceUtil.getTraceId());
}
// 检查RPC调用深度
checkRpcDeep(request, response);
// 业务处理
chain.doFilter(request, response);
// 记录RPC调用次数
logRpcCount(request, response);
} catch (Throwable ex) {
// 错误处理
Response<?> result = ExceptionUtil.toResponse(ex);
Determine determine = ExceptionUtil.determineType(ex);
ExceptionUtil.doLog(result, determine.getStatus(), ex);
response.setStatus(determine.getStatus().value());
response.setCharacterEncoding("UTF-8");
response.setContentType(MediaType.APPLICATION_JSON_UTF8_VALUE);
response.getWriter().write(JsonUtil.toJsonString(result));
} finally {
try {
doMonitor(request, response, startTime);
if (TraceUtil.isTraceLoggerOn()) {
log.warn(StringHelper.join(
"TRACE-HTTP-", request.getMethod(),
" URI:", request.getRequestURI(),
", dt:", System.currentTimeMillis() - startTime,
", rpc:", TraceUtil.getRpcCount(),
", status:", response.getStatus()));
} else if (log.isTraceEnabled()) {
log.trace(StringHelper.join(request.getMethod(),
" URI:", request.getRequestURI(),
", dt:", System.currentTimeMillis() - startTime,
", rpc:", TraceUtil.getRpcCount(),
", status:", response.getStatus()));
}
} finally {
ThreadLocalHolder.end(request);
}
}
}写在最后
一开始写代码的时候，没有规范日志的意识，不管哪里，都打个 INFO，打印出来的东西也没有思考过，有没有意义，其实让自己踩了不少坑，加了不少班，回过头，我想对学习时期的我说一句：”能让你加班的东西，都藏在各种细节里！写代码之前，先好好学习如何打日志！“