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

  1. 云栖社区>
  2. 博客>
  3. 正文

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

chad_chen 2017-11-24 15:36:08 浏览1524
展开阅读全文

集中式日志管理部署下的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



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

使用键值对输出的风格

上面的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());
  }
}

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

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

参考资料

网友评论

登录后评论
0/500
评论
chad_chen
+ 关注