一个结构化日志查看工具(一):为什么需要结构化日志

我要去首都学java

结构化日志,顾名思义不再是自由格式的日志,而是遵循了一定的结构:每一行日志就是一个JSON结构。好处显而易见:简化日志解析,使得日志的后续处理、分析或查询变得方便高效。

和结构化日志形成对比的就是传统的日志:一行或多行的字符串,字段之间主要是用空格等分隔符分隔开,输出格式自由定义。譬如下面是一个JAVA Spring-boot应用的几行日志:

image

所谓的输出格式可以自由定义意味着需要给上面这样的日志设置输出格式成:

%d{yyyy-MM-dd HH:mm:ss.SSS} %level ${application_name} trace=%X{X-B3-TraceId},span=%X{X-B3-SpanId} <%t> %c{40} - %msg%n

这种日志可以叫做是扁平化日志(flat log),缺点是不方便被ELK等日志系统处理,譬如Logstash里得配置grok正则表达式做好解析工作,转换出来的其实就是结构化了的日志,日志发送到Elasticsearch,然后我们就能跑Kibana里去查询。(既然最终发到Elasticsearch的就是结构化日志,那么干脆去掉解析?)。很明显,Logstash所做的解析的正确可靠与否对后续的日志分析和查找至关重要,其中的关键之一是grok正则表达式必须正确。问题在于正则表达式并不太好写,那么多日志格式,每种日志的每一个字段都要把grok正则表达式写正确才能解析,听上去就头大,写得正确不容易,写得要效率高更不容易,所以维护grok正则表达式是个又累又烦还容易出错的‘脏活’。到了现实中,大家还会这么想:反正Elasticsearch可以做全文检索,解析得精确不精确不会导致没法继续干活,那就不如不做解析直接扔给Elasticsearch得了。所以,在现实中,能做到把其中几个关键字段解析出来已经算是可以的了,根本就没有解析都不算少见 -- 常常是把整行日志作为一坨文本直接扔给了ELK,于是Kibana上查出来的日志就会这模样:

image

上面这条日志,连日志的时间和级别这样的基础字段都是混在了日志消息字段(即message字段)里,没解析出来,那譬如说我想查找指定时间范围里的ERROR级别的日志,就只能走全文检索了。现在日志经常以TB/PB计,那动辄就做全文检索能多快?还有,现在微服务/分布式系统成了主流,单个前端请求会跨越很多个服务,所以经常需要从不同来源的很多个服务的日志中提取出分布式跟踪系统附加的日志字段值(譬如前面例子里的X-B3-TraceId和X-B3-SpanId就是Spring Cloud Sleuth通过MDC加入日志的字段),把它们关联起来才能展现出一个完整的服务调用链查询,然后再对时间和其它业务字段组合起来做查询,这时候,全文检索在速度和准确性都满足不了要求,查不准确,容易带出一大片不相关的其它日志,还常常查询超时。可是我们又想,大部分查询条件其实只不过是多个‘字段=值’的AND/OR,简单直接的相等性比较完全足够啊,为什么原本应该很简单的事情会变成了到处都需要用全文检索去做?全文检索如果少了,效率就能提高了,可是前面解释了,这前提是原始日志里的字段要能够被准确地解析出来!所以,查询效率低下的主要原因之一也还是在于日志解析,让应用直接输出结构化日志不就解决问题了?那样的话,每条日志本来就是一个规范的JSON结构,结构的字段天然就是日志行的字段,不需要grok,直接发到ElasticSearch,Logstash也减少了对计算资源的消耗,简单直接、效率高,准确又可靠!

这就是为什么结构化日志日趋流行的主要原因。现在主流日志库基本上都支持输出JSON格式的结构化日志,譬如GO的Logrus和Zap,.NET的Serilog和NLog,JAVA的Log4j、Log4j2和Logback,甚至NODE.JS的激进的Bunyan只输出JSON日志。K8S和Docker这些,看上去打印出来的默认的还是传统的非结构化字符串日志,但其实存储下来的都是结构化日志了。MongoDB 4的日志也改成了结构化日志。

不过,事情要看两面:要把输出结构化日志做好其实也不仅仅是设置一下日志库的输出格式的事情,实际上程序员写日志的习惯也需要改改,这我后续另外写,在这里,我主要想说的是结构化日志同样也有缺点,不过基本上是可以接受或解决的,譬如我们容易想到的第一个是JSON格式里因为字段名字大量重复出现会导致日志文件变大,会占更多磁盘空间,占更多带宽,这个可以做压缩,压缩后几乎和传统文本日志压缩后的大小一样,而第二个缺点却是可能只会在程序员真正在日常中开始使用了结构化日志以后才意识到,因为我们会发觉自己tail -f看到的日志怎么变成这样了?

image

如果日志里有stacktrace,会这样:

image

这对机器来说是容易解析的,对运维和grok来说也是轻松的解脱,但我们的眼睛却是要花掉了。

那为什么不把JSON日志格式化一下,做对齐、缩进和换行,甚至字体加上颜色,打印得漂亮一些呢?通常我们不这么做,因为需要日志更紧凑些,格式化意味着额外的空白分隔符和字体颜色修饰符,格式化出来的单条日志可能占很多行,一屏能看到的日志条数会少许多,另外,我自己猜测,跨多行的话也不利于按行解析:结构化日志实际上并不符合JSON规范,虽然每一条日志是一个常规的JSON对象,但是很多条日志合起来后并没有用逗号分隔,开头没有左方括号,结尾也没有右方括号,换句话说,不是一个JSON数组。然后再琢磨一下:日志作为一种流式数据,也许在开头加个左方括号是容易的,那什么时候加上右方括号来表示结尾?另外,因为逗号同时也是JSON对象内部大量在用的分隔符,比不上换行符作为专门分隔符解析来得效率高,所以用换行符作为单条JSON日志的结尾标记的话,换行符号就不适合用在单条JSON日志内部了,JSON字段不得不挤在一起。这种很像JSON但却又不是JSON的格式,大数据处理里也常用到,还有专门的名字,叫做JSON Lines(http://jsonlines.org)。所以,回过头来再看,传统的非结构化字符串日志除了也不是一无是处,至少是比结构化日志方便查看。

对于这第二个问题一般有两种解决办法,一种是根据环境不同输出不同的格式:开发环境里输出传统格式以便肉眼查看,其它环境里就改成结构化输出,譬如logback.xml里可以这么设置:

image

或者,也可以根据输出目标的不同输出不同的格式,譬如命令行输出时用传统格式,而输出到日志文件时用结构化的,缺点在于需要翻阅日志文件去看历史记录时问题还是没得到解决,而且考虑到现在k8s环境下的主流日志收集方案之一是直接采集命令行输出作为日志,那样的话就又被绕回来了。

那么还有第二种解决办法,就是我想写的系列文章想推的专门的工具了,用工具可以边转换边查看,可以像tail或tail -f那样直接打开日志文件,或者把程序的命令行输出重定向到这个工具,由工具负责转换输出成传统的格式。这就不再需要我们在日志库设置文件里加上if/else,日志库只管输出结构化日志,简单直接,通过简单工具的组合使用完成复杂的工作很符合单一职责的设计原则。这种转换工具一开始就有了,譬如Bunyan和Zap就自带转换/查看工具,但现在我的选择是自己动手写了一个新的,推广自己的这个工具就是写这系列文章的动机。下面我先罗列了那些已有工具的几个主要缺点:

  1. 没有一个是通用的,因为没有统一的结构化日志的标准,所以各日志库和工具都是‘自扫门前雪’地只考虑给自己所属的日志库使用,譬如Bunyan是用数字来表示不同的日志级别的值,而Logback则会在日志时间字段名字前加个@,变成@timestamp,互相不识别。稍微上点规模的系统,都会有多种不同来源的日志格式,需要通用的简单直接的工具。
  2. 处理不了别的工具给加上的前缀,譬如为了把多个service的日志合并在一起输出时有所区分,docker-compose会在每条service日志前加上service名字作为前缀,输出成这样子:

image

而且,即使docker-compose不给加上前缀,那碰上service是MySQL这种还不支持结构化日志输出的呢?可想而知,那些只管自己专有格式的工具更是处理不了的。更糟糕些的还有,假如某个service是用pm2等进程管理工具启动的,那么还会被额外加上一层、变成两层的嵌套的前缀,这...?再譬如Springboot,即使我们改为始终输出JSON格式的日志,但是springboot最开始启动时会给我们加上一个Banner,如下图:

image

有点儿趣味和很像回事了,但是对Bunyan们的日志转换工具来说就是悲剧了。

  1. 不是所有时候都有ELK用,也不是所有时候都有必要动用ELK,这时我们一般是用grep或awk来搜索日志文件, grep们的主要缺点除了会截断跨多行打印的日志,还有个缺点是难以按时间范围搜索。特别是这条,以前用传统日志时,我们其实`是因为写正则表达式毕竟写起来比较麻烦就懒得花功夫去提取和转换日志里的时间,所以得过且过、需要用到按时间范围搜索时就只好靠眼睛盯着翻页,但现在既然有了结构化日志,从JSON里解析出一个时间值这么简单的事情是个程序员都会做,那提取出来按时间范围搜索不是很容易吗?这么简单的功能,Bunyan们居然没有(我猜是因为这不是它的重点,所以。。。),加上不难吧,挺有用啊!

不过值得推荐jq (https://stedolan.github.io/jq/), jq功能非常强大,结构化日志这种非常规的JSON数据它也能识别,能做很灵活的过滤转换和格式化输出,不过jq是个通用的json文件处理工具,没专门的日志工具使用起来那么方便,而且,碰到被添加了前缀的或者混合了的情况同样也处理不了,必须先用别的工具过滤掉。

总之,出于上面这几个原因,我就自己动手写了一个, 起名叫jog,取自json log的意思,一开始只有几十行代码,放在了公司git项目的某个目录里,后来用业余时间推倒了重新写,发布到了github(https://github.com/qiangyt/jog)。为了方便跨平台使用,jog是用GO写的,所以就一个可执行文件,跨平台,不用安装。这篇文章已经比较长了,到此结束,不准备写具体怎么使用了,不过实际上jog的基本用法很简单,就是个‘jog 文件名’,或者‘docker-compose logs | jog’,更多其它功能的用法打算放另一篇文字里专门写,下面给一个转换后的效果的截图,和一个'jog -h'打印出来的功能说明,完毕。

image

image

阅读 1.5k
1 声望
0 粉丝
0 条评论
你知道吗?

1 声望
0 粉丝
宣传栏