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

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

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

为什么Log输出变得越来越难

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

怎么变难的：

• 单线程同步：有时间戳和重要参数值就差不多了
• 多线程同步：你可能需要线程号（线程名）
• 单线程异步：比如Node.js，这个今天不聊
• 多线程异步：比如.Net异步编程，线程号没法用了，但是可以用AsyncLocal替代线程号
• 单机器多进程：好像也还好，登到机器上分别看也行
• 多机器多进程：完蛋，看个日志还得连到不同机器，就算同步日志文件到统一的文件服务器，也是太多
• 成百上千台服务器，复杂的服务调用：更完蛋，根本都没有权限登到服务器上去，这个时候引入了集中式日志管理

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

• 不同机器、进程、线程输出的Log丢到数据库里，需要有字段区分
• 不同服务、组件之间有调用，需要有字段关联
• Log的大小、跨行、格式解析带来各种古怪的问题

打Log要考虑的可能有：

• Log不能太多
• Log要使用合适的级别
• Log输出要尽可能快
• Log应包含哪些信息
• Log落盘之后会被转送到别处，这中间的坑要绕过去

我们现在是怎么打Log的

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

日志级别

• INFO还是DEBUG
  • 在生产环境DEBUG级别可能不会输出，所以尽可能用INFO，除非会导致日志过多性能下降（比如在一个用例的执行过程中会打印很多次的）
• ERROR还是WARN
  • 尽量不要用，如果一个错误程序可以处理，可能用WARN更合适，这样可以通过搜索ERROR找到你需要改代码的错误
• FATAL级别怎么用
  • FATAL或者CRITICAL可以理解为特别严重的错误，自然要谨慎对待，通常是需要运维快速介入的错误才需要用到这个级别
  • slf4j Logger接口没有fatal()方法，不过这没关系，就算有，也不建议使用。因为很有可能业务数据就包含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参数设置，这样在操作执行完时，可以决定回滚事务或者至少打印错误日志。

其它Log里需要输出的常用信息

• 调用端的IP端口
• 请求URL
• 线程名
• 源代码文件名和行号
• TraceID
• RequestID
• TenantID （对于多租户服务端）
• 用户ID
• 时间ID
• 异常栈 StackTrace（特别是对于未知异常）

七层负载均衡器

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

• 获取Client IP代码示例

public static String getClientIpAddr(HttpServletRequest request) {
  String ip = request.getHeader("x-forwarded-for");
  if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip)) {
    ip = request.getHeader("Proxy-Client-IP");
  }
  if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip)) {
    ip = request.getHeader("WL-Proxy-Client-IP");
  }
  if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip)) {
    ip = request.getRemoteAddr() + ":" + request.getRemotePort();
  }
  return ip;
}

日志输出格式

以 log4j 配置为例

• 一个典型的log4j.properties

# log4j configuration files
log4j.rootLogger=INFO, R

# rolling log file
log4j.appender.R=org.apache.log4j.RollingFileAppender
log4j.appender.R.encoding=UTF-8
log4j.appender.R.maxFileSize=20MB
log4j.appender.R.maxBackupIndex=50
log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.File=/var/log/test/test.log

# use %c to get better performance than %F
# log4j.appender.R.layout.ConversionPattern=%5p %d{ISO8601} [%t] %c %m%n
log4j.appender.R.layout.ConversionPattern=%5p %d{ISO8601} [%t] %F (line %L) %m%n

使用键值对输出的风格

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

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

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

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

{
  "log_level" : "INFO",
  "log_timestamp" : "2017-11-24T07:08:54,609",
  "log_thread" : "pool-5-thread-1",
  "log_class" : "ExecutorManager",
  "log_message" : "tryCount=50, consumeCount=3, consumeTimeMillis=1235",
  "tryCount" : 50,
  "consumeCount" : 3,
  "consumeTimeMillis" : 1235  
}

使用Json输出Log元数据

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

log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.encoding=UTF-8
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern
  ={"debug_level":"%p","debug_timestamp":"%d{ISO8601}",
    "debug_thread":"%t","debug_class":"%c","debug_message":"%m"}%n

特殊日志的处理

一行Log超级长

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

• 尽可能避免一行输出太长的Log，输出越多丢失的信息越多
• 如果一定要记录超大的一行记录，可以考虑拆分成多行输出

Exception StackTrace

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

public static void errorStackTrace(Logger logger, Exception e) {
  StackTraceElement[] stackTrace = e.getStackTrace();
  for (StackTraceElement stackTraceElement : stackTrace) {
    logger.error("\t at {}", stackTraceElement.toString());
  }
}

Json转义字符

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

一些小技巧

如何确定我的线程还活着

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

HeartbeatLogger heartbeatLogger = HeartbeatLoggerBuilder
    .aHeartbeatLogger()
    .withClassName(this.getClass().getSimpleName())
    .withIntervalSeconds(heartbeatIntervalSeconds)
    .withCustomerKeyValue("methodName", "checkMethodA")
    .build();
while(shouldKeepRunning) {
    heartbeatLogger.hearbeat();
}

在分布式流处理平台上，如何打印主机名和进程号

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

• Java Code

MDC.put("PID", pid);
MDC.put("HOSTNAME", hostName);

• log4j.properties ConversionPattern

%5p %d{ISO8601} [%X{HOSTNAME}] [%X{PID}] [%t] %c %m%n

• http://dev.splunk.com/view/logging-best-practices/SP-CAAADP6
• https://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/PatternLayout.html
• https://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/MDC.html