集中式日志管理部署下的Log输出

Log是程序记录执行过程，辅助排查问题的必备良药。随着后台程序越来越复杂，集群规模越来越大，通常会引入集中式程序日志管理，比如使用splunk或者ELK统一管理日志。Log打的好，排错无烦恼，但是往往打不好。下面就聊聊怎么打Log，特别是在使用集中式日志管理架构时。

一句话描述Log查找的需求：根据查询条件，返回并且仅返回所关注的用例相关的所有上下文。

怎么变难的：

单线程同步：有时间戳和重要参数值就差不多了

多线程同步：你可能需要线程号（线程名）

单线程异步：比如Node.js，这个今天不聊

多线程异步：比如.Net异步编程，线程号没法用了，但是可以用AsyncLocal替代线程号

单机器多进程：好像也还好，登到机器上分别看也行

多机器多进程：完蛋，看个日志还得连到不同机器，就算同步日志文件到统一的文件服务器，也是太多

成百上千台服务器，复杂的服务调用：更完蛋，根本都没有权限登到服务器上去，这个时候引入了集中式日志管理

对于单个进程，打Log需要考虑的问题会简单一些。集中式日志管理部署对Log查找带来新的问题：

不同机器、进程、线程输出的Log丢到数据库里，需要有字段区分

不同服务、组件之间有调用，需要有字段关联

Log的大小、跨行、格式解析带来各种古怪的问题

打Log要考虑的可能有：

Log不能太多

Log要使用合适的级别

Log输出要尽可能快

Log应包含哪些信息

Log落盘之后会被转送到别处，这中间的坑要绕过去

会有一些代码示例，这里用的是Java

INFO还是DEBUG

在生产环境DEBUG级别可能不会输出，所以尽可能用INFO，除非会导致日志过多性能下降（比如在一个用例的执行过程中会打印很多次的）

ERROR还是WARN

尽量不要用，如果一个错误程序可以处理，可能用WARN更合适，这样可以通过搜索ERROR找到你需要改代码的错误

FATAL级别怎么用

FATAL或者CRITICAL可以理解为特别严重的错误，自然要谨慎对待，通常是需要运维快速介入的错误才需要用到这个级别

slf4j Logger接口没有<code>fatal()</code>方法，不过这没关系，就算有，也不建议使用。因为很有可能业务数据就包含FATAL、CRITICAL字符串，如果你直接用，然后通过这两个字符串设置告警，就会有误报

所以应该定义产品自己的FATAL级日志的TAG，比如 XYZ_OP_CRITICAL ，然后可以这么打Log:

  ERROR 2015-09-08 18:46:19,333[main] App.java (line 37) we use XYZ_OP_CRITICAL as FATAL Tag,  

    XYZ_MODULE_ABC start failure due to connect DB failure.

哪些错误可以使用FATAL级别

程序启动失败

程序遇到了不可恢复的错误

...

尽量不要使用字符串格式化，特别是DEBUG级别的Log，直接把参数丢给Log库，这样可以节省字符格式化的计算开销

有些文章建议输出DEBUG级别Log之前判断一下是否Enable DEBUG级别，其实大多数时候没必要，因为Log库其实已经做了对应的优化

如果日志量可能很大，也许你需要考虑使用异步模式输出日志文件

日志输出格式也会影响输出性能，在下文会有说明

应该要输出启动日志

包含程序版本信息，最好还有编译时间

包含配置信息，但不包括敏感信息，比如数据库密码之类

批量接口

可以包含批量大小、成功数、失败数、成功占比

耗时事务操作

可以在事务结束时打印一行包括整个事务各个步骤的耗时

计数器类日志

可以通过单独的性能收集器实现

慢请求处理

请求延迟对于衡量服务质量非常重要，最好设置一个阈值，比如超过2秒的POST请求处理，超过100ms的GET请求处理单独记录，通常可以用拦截器实现

有时候请求处理耗时会超过客户端设定的Timeout，这个时候服务端就算处理成功了，客户端仍然认为是处理失败了，可能会重试。服务端程序最好支持客户端提供Timeout参数设置，这样在操作执行完时，可以决定回滚事务或者至少打印错误日志。

调用端的IP端口

请求URL

线程名

源代码文件名和行号

TraceID

RequestID

TenantID （对于多租户服务端）

用户ID

时间ID

异常栈 StackTrace（特别是对于未知异常）

当你的Web服务部署在七层负载均衡服务器后面时，没有办法直接获取到客户端的IP端口信息，你可能需要从HTTP head里取值。

获取Client IP代码示例

以 log4j 配置为例

一个典型的log4j.properties

注意<code>PatternLayout</code>的<code>ConversionPattern</code>配置，和性能相关。如果输出内容包含调用位置信息（<code>%F</code>文件名, <code>%M</code>方法名, <code>%L</code>代码行），性能会下降很多（大概是5~10倍差别）。如果发现日志会影响程序性能，就需要避免输出调用位置信息，其实用类名<code>%c</code>替代文件名<code>%F</code>大部分时候已经够用了。

上面的<code>ConversionPattern</code>配置影响的是代码行输出Log内容相关元数据，按照最普通的方式输出，如果需要把Log的一行内容解析到不同字段，可以使用正则匹配抽取。如果对抽取过程的性能有较高要求，还可以使用每个字段固定宽度的方式输出，这样可以按照字节长度截取得到不同字段的信息。

不足之处在于，对于自定义字段，没有办法很方便的抽取。这里推荐一种键值对输出风格，特别适合对Log内容进行预处理，解析到不同的字段，输出样例如下：

<code>INFO 2017-11-24T07:08:54,609 [pool-5-thread-1] [ExecutorManager] tryCount=50, consumeCount=3, consumeTimeMillis=1235</code>

元数据可以通过正则匹配，自定义内容可以通过kv提取函数匹配，解析到不同字段的值样例如下：

可以直接使用PatternLayout，一个比较取巧的方式，只需要保证<code>%m</code>的内容是一个普通字符串就可以了。

太长的Log可能会在传输过程中被截断，比如Logstash默认只保留一行Log的前8013个字节。所以：

尽可能避免一行输出太长的Log，输出越多丢失的信息越多

如果一定要记录超大的一行记录，可以考虑拆分成多行输出

因为集中式日志管理按照行为单位来存储日志，但是用<code>error()</code>方法打印Exception的时候只有第一行包含 Log元数据（机器信息、时间戳、线程名之类）。所以可能需要特殊处理，比如：

注意上面制表符之后还跟了个空格，因为有时候日之库会直接存<code>\t</code>，和后面的内容黏连在一起

Json本身支持转义字符，有时候我们一些Class的field本省存储的就是一个Json String，这个时候再输出，完蛋，好多个斜杠，就像这样<code>\\\\\n</code>之类的。日志库可能处理的不太好，尽量避免这种用法。

对于一些常驻线程，可能包含对某个方法的高频调用，每次都打Log的话量太多。可以写个HeartbeatLogger类，支持设定心跳间隔，比如每隔5分钟才打印一次。 我们是这么用的：

可以使用 MDC（Mapped Diagnostic Context），在log4j里使用 <code>%X</code>引用设置的变量。

Java Code

log4j.properties ConversionPattern

参考资料

<a href="http://dev.splunk.com/view/logging-best-practices/SP-CAAADP6">http://dev.splunk.com/view/logging-best-practices/SP-CAAADP6</a>

<a href="https://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/PatternLayout.html">https://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/PatternLayout.html</a>

<a href="https://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/MDC.html">https://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/MDC.html</a>