谈谈日志的最佳实践

谈谈日志的最佳实践

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)'

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一样可以完成我们日志的功能,只是第三方工具不是万能,他只能帮助我们检查即将出现的一些数据,历史的数据还是得靠我们的日志系统去保证。

总结

当然日志的实践优化不仅仅上上面这些点,还有更多的场景需要结合实际业务去进行优化。这里希望大家能使用好日志,让天下没有难排查的问题!

如果大家觉得这篇文章对你有帮助,你的关注和转发是对我最大的支持,O(∩_∩)O:


原文:https://my.oschina.net/u/4072299/blog/4282559
作者:咖啡拿铁的技术分享