stdout（只是不会写正则表达式而已）

日志收集的时候多行日志一直是一个比较头疼的问题，开发人员并不愿意将日志以 JSON 的方式进行输出，那么就只能在收集日志的时候去重新对日志做下结构化了。

由于日志采集器的实现方式和标准不一样，所以具体如何处理多行日志不同的采集器也会不一样的，比如这里我们使用 Fluentd 来作为日志采集器，那么我们就可以使用 multiline 这个解析器来处理多行日志。

多行解析器使用 formatN 和 format_firstline 参数解析日志，format_firstline 用于检测多行日志的起始行。formatN，其中 N 的范围是 [1..20]，是多行日志的 Regexp 格式列表。

测试数据

比如现在我们有如下所示的多行日志数据：

2022-06-20 19:32:07.264 DEBUG 7 [TID:bb0e9b6d1d704755a93ea1529265bb99.68.16557246000000125] --- [ scheduling-4] o.s.d.redis.core.RedisConnectionUtils : Closing Redis Connection. 2022-06-20 19:32:07.264 DEBUG 7 [TID:bb0e9b6d1d704755a93ea1529265bb99.68.16557246000000125] --- [ scheduling-4] io.lettuce.core.RedisChannelHandler : dispatching command AsyncCommand [type=DEL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command] 2022-06-20 17:28:27.871 DEBUG 6 [TID:N/A] --- [ main] o.h.l.p.build.spi.LoadPlanTreePrinter : LoadPlan(entity=com.xxxx.entity.ScheduledLeadsInvalid) - Returns - EntityReturnImpl(entity=com.xxxx.entity.ScheduledLeadsInvalid, querySpaceUid=<gen:0>, path=com.xxxx.entity.ScheduledLeadsInvalid) - QuerySpaces - EntityQuerySpaceImpl(uid=<gen:0>, entity=com.xxxx.entity.ScheduledLeadsInvalid) - SQL table alias mapping - scheduledl0_ - alias suffix - 0_ - suffixed key columns - {id1_51_0_} 2022-06-20 19:32:47.062 DEBUG 7 [TID:N/A] --- [nection-cleaner] h.i.c.PoolingHttpClientConnectionManager : Closing connections idle longer than 60000 MILLISECONDS

首先创建一个 fluentd 目录，在下面创建用于保存 fluentd 的配置文件 etc 目录和保存日志的 logs 目录，将上面的测试日志保存在 logs/test.log 文件中

$ mkdir fluentd $ cd fluentd # 创建用于保存 fluentd 的配置文件 etc 目录和保存日志的 logs 目录 $ mkdir -p etc logs

常规解析

然后创建一个用于解析日志的 fluentd 配置文件 etcd/fluentd_basic.conf，内容如下所示：

<source> @type tail path /fluentd/logs/*.log pos_file /fluentd/logs/test.log.pos tag test.logs read_from_head true <parse> @type regexp expression /^(?<timestamp>[^ ]* [^ ]*) (?<level>[^s]+) (?<pid>[^s+]+) [TID:(?<tid>[,a-z0-9A-Z./]+)] --- [(?<thread>.*)] (?<message>[sS]*)/ </parse> </source> <match **> @type stdout </match>

然后我们使用 docker 镜像的方式来启动 fluentd 解析我们的日志：

$ docker run --rm -v $(pwd)/etc:/fluentd/etc -v $(pwd)/logs:/fluentd/logs fluent/fluentd:v1.14-1 -c /fluentd/etc/fluentd_basic.conf -v fluentd -c /fluentd/etc/fluentd_basic.conf -v 2022-06-20 12:31:17 +0000 [info]: fluent/log.rb:330:info: parsing config file is succeeded path="/fluentd/etc/fluentd_basic.conf" 2022-06-20 12:31:17 +0000 [info]: fluent/log.rb:330:info: gem 'fluentd' version '1.14.3' 2022-06-20 12:31:17 +0000 [warn]: fluent/log.rb:351:warn: define <match fluent.**> to capture fluentd logs in top level is deprecated. Use <label @FLUENT_LOG> instead 2022-06-20 12:31:17 +0000 [info]: fluent/log.rb:330:info: using configuration file: <ROOT> <source> @type tail path "/fluentd/logs/*.log" pos_file "/fluentd/logs/test.log.pos" tag "test.logs" read_from_head true <parse> @type "regexp" expression /^(?<timestamp>[^ ]* [^ ]*) (?<level>[^s]+) (?<pid>[^s+]+) [TID:(?<tid>[,a-z0-9A-Z./]+)] --- [(?<thread>.*)] (?<message>[sS]*)/ unmatched_lines </parse> </source> <match **> @type stdout </match> </ROOT> 2022-06-20 12:36:21 +0000 [info]: fluent/log.rb:330:info: starting fluentd-1.14.3 pid=10 ruby="2.7.5" 2022-06-20 12:36:21 +0000 [info]: fluent/log.rb:330:info: spawn command to main: cmdline=["/usr/bin/ruby", "-Eascii-8bit:ascii-8bit", "/usr/bin/fluentd", "-c", "/fluentd/etc/fluentd_basic.conf", "-v", "--plugin", "/fluentd/plugins", "--under-supervisor"] 2022-06-20 12:36:22 +0000 [info]: fluent/log.rb:330:info: adding match pattern="**" type="stdout" 2022-06-20 12:36:22 +0000 [info]: fluent/log.rb:330:info: adding source type="tail" 2022-06-20 12:36:22 +0000 [warn]: #0 fluent/log.rb:351:warn: define <match fluent.**> to capture fluentd logs in top level is deprecated. Use <label @FLUENT_LOG> instead 2022-06-20 12:36:22 +0000 [info]: #0 fluent/log.rb:330:info: starting fluentd worker pid=19 ppid=10 worker=0 2022-06-20 12:36:22 +0000 [DEBUG]: #0 fluent/log.rb:309:debug: tailing paths: target = /fluentd/logs/test.log | existing = 2022-06-20 12:36:22 +0000 [info]: #0 fluent/log.rb:330:info: following tail of /fluentd/logs/test.log 2022-06-20 12:36:22 +0000 [warn]: #0 fluent/log.rb:351:warn: pattern not matched: " - Returns" 2022-06-20 12:36:22 +0000 [warn]: #0 fluent/log.rb:351:warn: pattern not matched: " - EntityReturnImpl(entity=com.xxxx.entity.ScheduledLeadsInvalid, querySpaceUid=<gen:0>, path=com.xxxx.entity.ScheduledLeadsInvalid)" 2022-06-20 12:36:22 +0000 [warn]: #0 fluent/log.rb:351:warn: pattern not matched: " - QuerySpaces" 2022-06-20 12:36:22 +0000 [warn]: #0 fluent/log.rb:351:warn: pattern not matched: " - EntityQuerySpaceImpl(uid=<gen:0>, entity=com.xxxx.entity.ScheduledLeadsInvalid)" 2022-06-20 12:36:22 +0000 [warn]: #0 fluent/log.rb:351:warn: pattern not matched: " - SQL table alias mapping - scheduledl0_" 2022-06-20 12:36:22 +0000 [warn]: #0 fluent/log.rb:351:warn: pattern not matched: " - alias suffix - 0_" 2022-06-20 12:36:22 +0000 [warn]: #0 fluent/log.rb:351:warn: pattern not matched: " - suffixed key columns - {id1_51_0_}" 2022-06-20 12:36:22 +0000 [warn]: #0 fluent/log.rb:351:warn: pattern not matched: "" 2022-06-20 12:36:22.308970489 +0000 test.logs: {"timestamp":"2022-06-20 19:32:07.264","level":"DEBUG","pid":"7","tid":"bb0e9b6d1d704755a93ea1529265bb99.68.16557246000000125","thread":" scheduling-4","message":"o.s.d.redis.core.RedisConnectionUtils : Closing Redis Connection."} 2022-06-20 12:36:22.309013403 +0000 test.logs: {"timestamp":"2022-06-20 19:32:07.264","level":"DEBUG","pid":"7","tid":"bb0e9b6d1d704755a93ea1529265bb99.68.16557246000000125","thread":" scheduling-4","message":"io.lettuce.core.RedisChannelHandler : dispatching command AsyncCommand [type=DEL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]"} 2022-06-20 12:36:22.309025559 +0000 test.logs: {"timestamp":"2022-06-20 17:28:27.871","level":"DEBUG","pid":"6","tid":"N/A","thread":" main","message":"o.h.l.p.build.spi.LoadPlanTreePrinter : LoadPlan(entity=com.xxxx.entity.ScheduledLeadsInvalid)"} 2022-06-20 12:36:22.309715537 +0000 test.logs: {"timestamp":"2022-06-20 19:32:47.062","level":"DEBUG","pid":"7","tid":"N/A","thread":"nection-cleaner","message":"h.i.c.PoolingHttpClientConnectionManager : Closing connections idle longer than 60000 MILLISECONDS"} 2022-06-20 12:36:22 +0000 [info]: #0 fluent/log.rb:330:info: fluentd worker is now running worker=0 2022-06-20 12:36:22.305753588 +0000 fluent.info: {"pid":19,"ppid":10,"worker":0,"message":"starting fluentd worker pid=19 ppid=10 worker=0"} 2022-06-20 12:36:22.308522121 +0000 fluent.debug: {"message":"tailing paths: target = /fluentd/logs/test.log | existing = "} 2022-06-20 12:36:22.308751095 +0000 fluent.info: {"message":"following tail of /fluentd/logs/test.log"} 2022-06-20 12:36:22.309047520 +0000 fluent.warn: {"message":"pattern not matched: " - Returns""} 2022-06-20 12:36:22.309180634 +0000 fluent.warn: {"message":"pattern not matched: " - EntityReturnImpl(entity=com.xxxx.entity.ScheduledLeadsInvalid, querySpaceUid=<gen:0>, path=com.xxxx.entity.ScheduledLeadsInvalid)""} 2022-06-20 12:36:22.309258667 +0000 fluent.warn: {"message":"pattern not matched: " - QuerySpaces""} 2022-06-20 12:36:22.309328608 +0000 fluent.warn: {"message":"pattern not matched: " - EntityQuerySpaceImpl(uid=<gen:0>, entity=com.xxxx.entity.ScheduledLeadsInvalid)""} 2022-06-20 12:36:22.309401309 +0000 fluent.warn: {"message":"pattern not matched: " - SQL table alias mapping - scheduledl0_""} 2022-06-20 12:36:22.309468557 +0000 fluent.warn: {"message":"pattern not matched: " - alias suffix - 0_""} 2022-06-20 12:36:22.309563730 +0000 fluent.warn: {"message":"pattern not matched: " - suffixed key columns - {id1_51_0_}""} 2022-06-20 12:36:22.309723704 +0000 fluent.warn: {"message":"pattern not matched: """} 2022-06-20 12:36:22.310086626 +0000 fluent.info: {"worker":0,"message":"fluentd worker is now running worker=0"}

从上面的解析结果可以看出，正则表达式有一部分没匹配，有一些可以正常解析，比如下面的日志就是前面的一行日志解析出来后的结果：

{"timestamp":"2022-06-20 19:32:07.264","level":"DEBUG","pid":"7","tid":"bb0e9b6d1d704755a93ea1529265bb99.68.16557246000000125","thread":" scheduling-4","message":"o.s.d.redis.core.RedisConnectionUtils : Closing Redis Connection."}

而没有正常匹配的是多行日志，fluentd 会将每一个日志行当成独立的一行进行处理，这显然不符合我们的预期。

多行解析器

我们希望的是能将多行日志当成一行日志进行处理，这里就需要用到 multiline 这个解析器了，新建一个用于多行日志处理的配置文件 etc/fluentd_multline.conf，内容如下所示：

<source> @type tail path /fluentd/logs/*.log pos_file /fluentd/logs/test.log.pos tag test.logs read_from_head true <parse> @type multiline format_firstline /d{4}-d{1,2}-d{1,2}/ format1 /^(?<timestamp>[^ ]* [^ ]*) (?<level>[^s]+) (?<pid>[^s+]+) [TID:(?<tid>[,a-z0-9A-Z./]+)] --- [(?<thread>.*)] (?<message>[sS]*)/ </parse> </source> <match **> @type stdout </match>

这里面我们使用 format_firstline /d{4}-d{1,2}-d{1,2}/ 来匹配每一行日志的开头，format1 用来解析第一行日志，如果你还有更多数据需要匹配，则可以继续配置第二行 format2 的匹配规则等等，使用上面这个配置重新启动 fluentd：

docker run --rm -v $(pwd)/etc:/fluentd/etc -v $(pwd)/logs:/fluentd/logs fluent/fluentd:v1.14-1 -c /fluentd/etc/fluentd_multline.conf -v fluentd -c /fluentd/etc/fluentd_multline.conf -v 2022-06-20 12:41:58 +0000 [info]: fluent/log.rb:330:info: parsing config file is succeeded path="/fluentd/etc/fluentd_multline.conf" 2022-06-20 12:41:58 +0000 [info]: fluent/log.rb:330:info: gem 'fluentd' version '1.14.3' 2022-06-20 12:41:58 +0000 [warn]: fluent/log.rb:351:warn: define <match fluent.**> to capture fluentd logs in top level is deprecated. Use <label @FLUENT_LOG> instead 2022-06-20 12:41:58 +0000 [info]: fluent/log.rb:330:info: using configuration file: <ROOT> <source> @type tail path "/fluentd/logs/*.log" pos_file "/fluentd/logs/test.log.pos" tag "test.logs" read_from_head true <parse> @type "multiline" format_firstline "/\d{4}-\d{1,2}-\d{1,2}/" format1 /^(?<timestamp>[^ ]* [^ ]*) (?<level>[^s]+) (?<pid>[^s+]+) [TID:(?<tid>[,a-z0-9A-Z./]+)] --- [(?<thread>.*)] (?<message>[sS]*)/ unmatched_lines </parse> </source> <match **> @type stdout </match> </ROOT> 2022-06-20 12:41:58 +0000 [info]: fluent/log.rb:330:info: starting fluentd-1.14.3 pid=9 ruby="2.7.5" 2022-06-20 12:41:58 +0000 [info]: fluent/log.rb:330:info: spawn command to main: cmdline=["/usr/bin/ruby", "-Eascii-8bit:ascii-8bit", "/usr/bin/fluentd", "-c", "/fluentd/etc/fluentd_multline.conf", "-v", "--plugin", "/fluentd/plugins", "--under-supervisor"] 2022-06-20 12:41:59 +0000 [info]: fluent/log.rb:330:info: adding match pattern="**" type="stdout" 2022-06-20 12:41:59 +0000 [info]: fluent/log.rb:330:info: adding source type="tail" 2022-06-20 12:41:59 +0000 [warn]: #0 fluent/log.rb:351:warn: define <match fluent.**> to capture fluentd logs in top level is deprecated. Use <label @FLUENT_LOG> instead 2022-06-20 12:41:59 +0000 [info]: #0 fluent/log.rb:330:info: starting fluentd worker pid=18 ppid=9 worker=0 2022-06-20 12:41:59 +0000 [debug]: #0 fluent/log.rb:309:debug: tailing paths: target = /fluentd/logs/test.log | existing = 2022-06-20 12:41:59 +0000 [info]: #0 fluent/log.rb:330:info: following tail of /fluentd/logs/test.log 2022-06-20 12:41:59.201105512 +0000 test.logs: {"timestamp":"2022-06-20 19:32:07.264","level":"DEBUG","pid":"7","tid":"bb0e9b6d1d704755a93ea1529265bb99.68.16557246000000125","thread":" scheduling-4","message":"o.s.d.redis.core.RedisConnectionUtils : Closing Redis Connection."} 2022-06-20 12:41:59.201140475 +0000 test.logs: {"timestamp":"2022-06-20 19:32:07.264","level":"DEBUG","pid":"7","tid":"bb0e9b6d1d704755a93ea1529265bb99.68.16557246000000125","thread":" scheduling-4","message":"io.lettuce.core.RedisChannelHandler : dispatching command AsyncCommand [type=DEL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]"} 2022-06-20 12:41:59.201213082 +0000 test.logs: {"timestamp":"2022-06-20 17:28:27.871","level":"DEBUG","pid":"6","tid":"N/A","thread":" main","message":"o.h.l.p.build.spi.LoadPlanTreePrinter : LoadPlan(entity=com.xxxx.entity.ScheduledLeadsInvalid)n - Returnsn - EntityReturnImpl(entity=com.xxxx.entity.ScheduledLeadsInvalid, querySpaceUid=<gen:0>, path=com.xxxx.entity.ScheduledLeadsInvalid)n - QuerySpacesn - EntityQuerySpaceImpl(uid=<gen:0>, entity=com.xxxx.entity.ScheduledLeadsInvalid)n - SQL table alias mapping - scheduledl0_n - alias suffix - 0_n - suffixed key columns - {id1_51_0_}"} 2022-06-20 12:41:59 +0000 [info]: #0 fluent/log.rb:330:info: fluentd worker is now running worker=0 2022-06-20 12:41:59.199950788 +0000 fluent.info: {"pid":18,"ppid":9,"worker":0,"message":"starting fluentd worker pid=18 ppid=9 worker=0"} 2022-06-20 12:41:59.200662918 +0000 fluent.debug: {"message":"tailing paths: target = /fluentd/logs/test.log | existing = "} 2022-06-20 12:41:59.200844577 +0000 fluent.info: {"message":"following tail of /fluentd/logs/test.log"} 2022-06-20 12:41:59.201480874 +0000 fluent.info: {"worker":0,"message":"fluentd worker is now running worker=0"}

可以看到现在获取到的日志就正常了，前面的多行日志也按我们的预期解析成一行日志了：

{"timestamp":"2022-06-20 17:28:27.871","level":"DEBUG","pid":"6","tid":"N/A","thread":" main","message":"o.h.l.p.build.spi.LoadPlanTreePrinter : LoadPlan(entity=com.xxxx.entity.ScheduledLeadsInvalid)n - Returnsn - EntityReturnImpl(entity=com.xxxx.entity.ScheduledLeadsInvalid, querySpaceUid=<gen:0>, path=com.xxxx.entity.ScheduledLeadsInvalid)n - QuerySpacesn - EntityQuerySpaceImpl(uid=<gen:0>, entity=com.xxxx.entity.ScheduledLeadsInvalid)n - SQL table alias mapping - scheduledl0_n - alias suffix - 0_n - suffixed key columns - {id1_51_0_}"}

当然这整个过程并不复杂，唯一麻烦的地方需要我们去「编写正则表达式」去匹配日志，这可能才是难倒大部分人的一个问题吧~

k8s技术圈