谈谈日志的最佳实践

栏目: IT技术 · 发布时间: 4年前

内容简介：日志是我们程序员的一个老生常谈的话题，你可能每天都会听到这个词。想起我刚刚大学毕业的时候刚进入公司，正逢做一些部门业务交接，也就是其他部门的服务交给我们维护。记得没交接多久，当时业务上微信公众号相关功能就出现了不可用，当时负责这部分业务的同学，排查问题及其艰难，整个链路一个日志都没打，就在入口处error日志，连续上了好几次线，加了好几轮日志，才把问题给定位住了。当时其他部门也出现了另外一个例子，日志打得太多了，由于业务访问的量级，导致大量日志打出，从而让磁盘IO打满，最后让整个服务瘫痪。时间一晃就过了好几

1.背景

日志是我们程序员的一个老生常谈的话题，你可能每天都会听到这个词。想起我刚刚大学毕业的时候刚进入公司，正逢做一些部门业务交接，也就是其他部门的服务交给我们维护。记得没交接多久，当时业务上微信公众号相关功能就出现了不可用，当时负责这部分业务的同学，排查问题及其艰难，整个链路一个日志都没打，就在入口处error日志，连续上了好几次线，加了好几轮日志，才把问题给定位住了。当时其他部门也出现了另外一个例子，日志打得太多了，由于业务访问的量级，导致大量日志打出，从而让磁盘IO打满，最后让整个服务瘫痪。

时间一晃就过了好几年，但是上面这样的问题在不同的公司，不同的部门都在上演着，很多开发人员为了图自己的一些方便，不重视日志的使用，有时候如果一直是你维护也还行，出了问题由于是你开发的，可能你一眼就能发现，但如果你的代码交接出去，让其他人进行维护。平时也有一些公众号的读者会向我咨询日志使用的一些问题，于是我在这里结合平时的一些使用经验还有《阿里巴巴 java 开发手册》，写一下我认为的日志最佳实践。

2.最佳实践

2.1 合理的级别划分

在日志系统中有6种级别来控制我们日志的输出：

TRACE: 在线调试，这个基本没有使用过，比较鸡肋。
DEBUG: 用于调试的日志，如果信息不是很重要，只是在某些极端的场景才会需要，那么就可以使用DEBUG。
INFO: INFO信息通常用于某些日志输出需要常态化，需要经常使用它，我们排查一些业务问题经常也需要这部分信息，那么你就可以使用INFO。
WARNING：警告信息，通常用于一些已知的业务错误，这部分错误基本能处理。
ERROR: 错误信息，通常用于我们无法处理的异常或者错误，对于这部分应该使用ERROR。
FATAL: 致命的错误，代表这程序需要马上终止，这个用得也很少，在业务使用中我们也不会使用

虽然有6种日志级别，但是我们在真正的业务开发中需要关注的业务级别一般来说只有3种，TRACE和FATAL这两个基本不会使用，DEBUG在一些基础工具开发中我们使用得比较多，因为这些基础工具打印日志是对于业务方来说是隐式打印，所以如果不是太重要的信息都需要使用debug。

对于ERROR和WARN这两种日志其实有挺多同学都会混用，通常来说出现ERROR日志会发各种提醒，比如短信这些，有一些同学老是把所有错误都给打成ERROR,比如用户没有权限，用户余额不足等等，那么难免少不了短信轰炸。其实这部分错误其实是属于我们业务流程中的一部分，那么其实应该使用WARN打印日志就够了。这里给大家推荐一个好的方法,来处理这种情况，我们将所有的业务异常都继承一个异常，在我们的业务中是BizException，通过捕获这部分异常去打WARN日志。

        try{
            // do something
        }catch (BizException e){
            LOG.warn("biz exception", e);
        }catch (Exception e){
            LOG.error("exception", e);
        }

当然这部分逻辑也可以通过切面去处理，把异常信息尽量塞入到exception中，统一去处理。

动态日志级别调整

我们上面讲了日志有6种级别，但是我们对于一个日志系统来说会有一个整体的级别的选择，通常在业务中我们会选择info，也就是我们输出的日志级别大于等于info就会被输出到文件中。我们想想下面的两种情况：

在某个业务中触发了一个bug,大量的打出error日志，不仅影响机器的性能，并且还频繁的发出错误短信。
需要排查某个基础工具中间件的问题，但是日志级别是debug，这个时候需要重新上线修改日志级别为debug排查问题。

这两种场景都可以利用动态日志级别调整去解决，当大量出现error日志的时候，可以立即把日志关闭，防止由于打印日志引发更多的问题。当需要排查一些debug级别的问题的时候，直接修改到debug输出级别就能满足需要。

动态日志级别调整的方法一般有下面几种方法：

如果是spring-boot 1.5之后的版本，引入spring-boot-starter-actuator，通过http接口修改日志级别。
使用arthas，通过ognl修改，如下面代码所示：

ognl -c 1be6f5c3 '@org.slf4j.LoggerFactory@getLogger("root").setLevel(@ch.qos.logback.classic.Level@DEBUG)'

自己开发一套支持http协议修改级别的工具，之前美团有一篇文章(https://tech.meituan.com/2017/02/17/change-log-level.html)可以参考

2.2 合理的使用占位符

有一道经典面试题，如下面代码所示，你能找到这个代码的问题在哪吗？

        LOG.info("a:" + a + "b" + b );

如果我们日志输出级别是warn，那么我们的info日志实际上是不会打印的，但是里面的字符串相加这个操作确实会被执行，所以为了出现这个问题，之前很多人都会加一个级别判断：

        if (LOG.isInfoEnabled()){
            LOG.info("a:" + a + "b" + b );
        }

但是这么写，就会导致有点拖沓，于是就出现了占位符的写法：

        LOG.info("a:{}, b:{}", a, b);

这里一行代码就完成，这里要说明的是日志服务并没有做特别的事，占位符的替换依旧是通过MessageFormat这个类去做的，也就是会一个一个的遍历，所以在这里唯品会java手册上推荐如果是ERROR的日志，推荐使用上面的“a” + a + “b:” + b这种模式，因为ERROR一般来说都需要每次打印，所以不需要担心白做了String的拼接。我个人觉得没必要为了占位符的这点性能做太多的考虑，你info都使用了占位符，一般来说info的日志占据了这个系统99%的日志，只有那么1%的error日志，所以提升一般是不大的，并且反而会让人产生错用的可能。

异常不用占位符

     try{
           // do something
       }catch (Exception e){
           LOG.error("exception :{}", e);
       }

很多人在打印异常的时候都会像上面那样去写，占位符填充的时候其实取的就是toString方法，那么如果直接调用异常的toString就会导致异常的堆栈信息丢失，从而加大我们排查问题的难度，所以这里要强调如果打印异常不能直接用占位符，而是直接写在末尾，日志打印的时候会自动打印出一场的堆栈信息。

2.3 合理的选择日志输出方式

日志输出的模式分为两种：同步和异步模式。我们在业务中一般来说会选择异步模式，在log4j2中异步模式分为两种：

AsyncAppender：使用ArrayBlockingQueue保存异步日志，然后使用一个异步线程输出。
AsyncLogger：使用Disruptor框架保存日志，然后使用一个异步线程输出。

对于Disruptor之前写过一篇文章:详解Disruptor,这是一个高性能队列，如果我们在log4j2中使用Dirsruptor会增加日志输出吞吐量。但是Disruptor的日志输出模式，我们一般用得比较少，之前在美团的时候因为用Disruptor输出日志，造成了cpu打满的情况，所以Disruptor输出日志在有些地方是被禁止使用的。一般来说AsyncAppender就能满足我们的使用了。

2.4 合理的保存日志

当我们思考清楚日志的输出方式之后，我们就可以考虑如何保存日志，因为我们的磁盘空间不是无限的，我们就需要考虑日志的过期删除，阿里巴巴java开发手册中明确的强制要求我们至少保存15天日志，对于用户的敏感操作和重要的日志，需要6个月的保存时间，在log4j2中也可以通过下面的配置进行日志删除操作：

<DefaultRolloverStrategy max="30">
                <Delete basePath="${LOG_HOME}/" maxDepth="2">
                    <IfFileName glob="*.log" />
                    <IfLastModified age="30d" />
                </Delete>
            </DefaultRolloverStrategy>

这里就代表这最多保存30天的日志，当然也可以在机器上面配置个定时任务进行删除。

有时候我们的机器比较多当我们排查某个问题的时候，最原始的方法我们会一个一个的机器上去看，后面我们又开始用polysh，只需要在一台机器上面执行命令，其他机器就会自动执行，但是这样还是有点不方便，所以后面又出来了ELK，我们使用Logstash收集所有的日志然后存储到Elasticsearch，最后使用Kibana进行可视化界面分析。所以使用Elasticsearch存储日志也是一个不错的办法。

2.5 合理的输出日志

在我们的系统中，如果输出大量的无效日志，会影响我们的系统的性能，所以我们的日志的打印也需要进行思考，哪些地方对我们有帮助，而不是一股脑的全部打出。

我们在通过日志排查问题的时候，通常会跨服务，有时候这个日志的信息不是能很好的对应上，所以我们这个时候就需要有一个东西去把他们给关联上，在这里的话就是traceId，我们通过一个traceId就可以拿到整个链路中的日志信息，对我们的日志排查特别方便。

2.6 不要有敏感信息

在2018年的时候facebook数据泄密，那个时候整个互联网突然开始重视起来敏感信息的泄漏，在日志系统中也是很容易泄密的，比如用户的姓名，手机号等等。如果打在日志中，很容易被不法分子盗用信息，所以我们在打印日志的时候要特别注意敏感信息的问题，具体的日志脱敏我之前也写过一篇文章有兴趣的可以看一下。手把手教你如何设计日志脱敏插件

2.7 合理的日志划分

有很多同学把所有日志都打在了同一个文件里面，对于我们的排查日志信息的时候特别不方便，我们可以把日志分成多个文件，比如根据不同的中间件，http,rpc,mq等等都可以单独搞成独立的日志文件，这下排查某个问题的时候就比较容易归纳查找。

2.8 第三方工具

虽然讲了这么多日志的一些规约，但是不可能很完美的每次都能打出我们想要的结果，比如某些方法可能没有加日志，但是又要排查一些问题。这个时候可以借用我们的第三方工具，比如arthas，我们使用arthas的很多命令比如watch,trace一样可以完成我们日志的功能，只是第三方工具不是万能，他只能帮助我们检查即将出现的一些数据，历史的数据还是得靠我们的日志系统去保证。