如何優雅收集和管理應用的多行日志
多行日志（例如異常信息）為調試應用問題提供了許多非常有價值的信息，在分布式微服務流行的今天基本上都會統一將日志進行收集，比如常見的 ELK、EFK 等方案，但是這些方案如果沒有適當的配置，它們是不會將多行日志看成一個整體的，而是每一行都看成獨立的一行日志進行處理，這對我們來說是難以接受的。
在本文中，我們將介紹一些常用日志收集工具處理多行日志的策略。
1JSON
保證多行日志作為單個事件進行處理最簡單的方法就是以 JSON 格式記錄日志，比如下面是常規 Java 日常日志的示例：
- # javaApp.log
- 2019-08-14 14:51:22,299 ERROR [http-nio-8080-exec-8] classOne: Index out of range
- java.lang.StringIndexOutOfBoundsException: String index out of range: 18
- at java.lang.String.charAt(String.java:658)
- at com.example.app.loggingApp.classOne.getResult(classOne.java:15)
- at com.example.app.loggingApp.AppController.tester(AppController.java:27)
- at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
- at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
- at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
- at java.lang.reflect.Method.invoke(Method.java:498)
- at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190)
- at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138)
- [...]
如果直接收集上面的日志會識別為多行日志，如果我們用 JSON 格式來記錄這些日志，然后介紹 JSON 的數據就簡單多了，比如使用 Log4J2 來記錄，變成下面的格式：
- {"@timestamp":"2019-08-14T18:46:04.449+00:00","@version":"1","message":"Index out of range","logger_name":"com.example.app.loggingApp.classOne","thread_name":"http-nio-5000-exec-6","level":"ERROR","level_value":40000,"stack_trace":"java.lang.StringIndexOutOfBoundsException: String index out of range: 18\n\tat java.lang.String.charAt(String.java:658)\n\tat com.example.app.loggingApp.classOne.getResult(classOne.java:15)\n\tat com.example.app.loggingApp.AppController.tester(AppController.java:27)\n\tat sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n\tat sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\n\tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat java.lang.reflect.Method.invoke(Method.java:498)\n\tat org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190)\n\tat org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138)\n\tat
- [...]
- }
這樣整個日志消息都包含在單個 JSON 對象匯總了，其中就包含完整的異常堆棧信息，絕大多數工具都支持直接解析 JSON 日志數據，這是最簡單的一種方法，對于運維同學來說也是最省心的，但是大部分開發人員是抵觸用 JSON 格式來記錄日志的~~~
2Logstash
對于使用 Logstash 的用戶來說，要支持多行日志也不困難，Logstash 可以使用插件解析多行日志，該插件在日志管道的 input 部分進行配置。例如，下面的配置表示讓 Logstash 匹配你的日志文件中 ISO8601 格式的時間戳，當匹配到這個時間戳的時候，它就會將之前所有不以時間戳開頭的內容折疊到之前的日志條目中去。
- input {
- file {
- path => "/var/app/current/logs/javaApp.log"
- mode => "tail"
- codec => multiline {
- pattern => "^%{TIMESTAMP_ISO8601} "
- negate => true
- what => "previous"
- }
- }
- }
3Fluentd
和 Logstash 類似，Fluentd 也允許我們使用一個插件來處理多行日志，我們可以配置插件接收一個或多個正則表達式，以下面的 Python 多行日志為例：
- 2019-08-01 18:58:05,898 ERROR:Exception on main handler
- Traceback (most recent call last):
- File "python-logger.py", line 9, in make_log
- return word[13]
- IndexError: string index out of range
如果沒有 multiline 多行解析器，Fluentd 會把每行當成一條完整的日志，我們可以在 <source> 模塊中添加一個 multiline 的解析規則，必須包含一個 format_firstline 的參數來指定一個新的日志條目是以什么開頭的，此外還可以使用正則分組和捕獲來解析日志中的屬性，如下配置所示：
- <source>
- @type tail
- path /path/to/pythonApp.log
- tag sample.tag
- <parse>
- @type multiline
- format_firstline /\d{4}-\d{1,2}-\d{1,2}/
- format1 /(?<timestamp>[^ ]* [^ ]*) (?<level>[^\s]+:)(?<message>[\s\S]*)/
- </parse>
- </source>
在解析部分我們使用 @type multiline 指定了多行解析器，然后使用 format_firstline 來指定我們多行日志開頭的規則，這里我們就用一個簡單的正則匹配日期，然后指定了其他部分的匹配模式，并為它們分配了標簽，這里我們將日志拆分成了 timestamp、level、message 這幾個字段。
經過上面的規則解析過后，現在 Fluentd 會將每個 traceback 日志看成一條單一的日志了：
- {
- "timestamp": "2019-08-01 19:22:14,196",
- "level": "ERROR:",
- "message": "Exception on main handler\nTraceback (most recent call last):\n File \"python-logger.py\", line 9, in make_log\n return word[13]\nIndexError: string index out of range"
- }
該日志已被格式化為 JSON，我們匹配的標簽也被設置為了 Key。
在 Fluentd 官方文檔中也有幾個示例說明：
-
Rails 日志
比如輸入的 Rails 日志如下所示：
- Started GET "/users/123/" for 127.0.0.1 at 2013-06-14 12:00:11 +0900
- Processing by UsersController#show as HTML
- Parameters: {"user_id"=>"123"}
- Rendered users/show.html.erb within layouts/application (0.3ms)
- Completed 200 OK in 4ms (Views: 3.2ms | ActiveRecord: 0.0ms)
我們可以使用下面的解析配置進行多行匹配：
- <parse>
- @type multiline
- format_firstline /^Started/
- format1 /Started (?<method>[^ ]+) "(?<path>[^"]+)" for (?<host>[^ ]+) at (?<time>[^ ]+ [^ ]+ [^ ]+)\n/
- format2 /Processing by (?<controller>[^\u0023]+)\u0023(?<controller_method>[^ ]+) as (?<format>[^ ]+?)\n/
- format3 /( Parameters: (?<parameters>[^ ]+)\n)?/
- format4 / Rendered (?<template>[^ ]+) within (?<layout>.+) \([\d\.]+ms\)\n/
- format5 /Completed (?<code>[^ ]+) [^ ]+ in (?<runtime>[\d\.]+)ms \(Views: (?<view_runtime>[\d\.]+)ms \| ActiveRecord: (?<ar_runtime>[\d\.]+)ms\)/
- </parse>
解析過后得到的日志如下所示：
- {
- "method" :"GET",
- "path" :"/users/123/",
- "host" :"127.0.0.1",
- "controller" :"UsersController",
- "controller_method":"show",
- "format" :"HTML",
- "parameters" :"{ \"user_id\":\"123\"}",
- ...
- }
-
Java 堆棧日志
比如現在我們要解析的日志如下所示：
- 2013-3-03 14:27:33 [main] INFO Main - Start
- 2013-3-03 14:27:33 [main] ERROR Main - Exception
- javax.management.RuntimeErrorException: null
- at Main.main(Main.java:16) ~[bin/:na]
- 2013-3-03 14:27:33 [main] INFO Main - End
則我們可以使用下面的解析規則進行多行匹配：
- <parse>
- @type multiline
- format_firstline /\d{4}-\d{1,2}-\d{1,2}/
- format1 /^(?<time>\d{4}-\d{1,2}-\d{1,2} \d{1,2}:\d{1,2}:\d{1,2}) \[(?<thread>.*)\] (?<level>[^\s]+)(?<message>.*)/
- </parse>
解析過后的日志為：
- {
- "thread" :"main",
- "level" :"INFO",
- "message":" Main - Start"
- }
- {
- "thread" :"main",
- "level" :"ERROR",
- "message":" Main - Exception\njavax.management.RuntimeErrorException: null\n at Main.main(Main.java:16) ~[bin/:na]"
- }
- {
- "thread" :"main",
- "level" :"INFO",
- "message":" Main - End"
- }
上面的多行解析配置中除了 format_firstline 指定多行日志的開始行匹配之外，還用到了 format1、format2…formatN 這樣的配置，其中 N 的范圍是 1...20，是多行日志的 Regexp 格式列表，為了便于配對，可以將 Regexp 模式分割成多個 regexpN 參數，將這些匹配模式連接起來構造出多行模式的正則匹配。
4Fluent Bit
Fluent Bit 的 tail input 插件也提供了處理多行日志的配置選項，比如現在我們還是來處理之前的 Python 多行日志：
- 2019-08-01 18:58:05,898 ERROR:Exception on main handler
- Traceback (most recent call last):
- File "python-logger.py", line 9, in make_log
- return word[13]
- IndexError: string index out of range
如果不用多行解析器 Fluent Bit 同樣會將每一行當成一條日志進行處理，我們可以配置使用 Fluent Bit 內置的 regex 解析器插件來結構化多行日志：
- [PARSER]
- Name log_date
- Format regex
- Regex /\d{4}-\d{1,2}-\d{1,2}/
- [PARSER]
- Name log_attributes
- Format regex
- Regex /(?<timestamp>[^ ]* [^ ]*) (?<level>[^\s]+:)(?<message>[\s\S]*)/
- [INPUT]
- Name tail
- tag sample.tag
- path /path/to/pythonApp.log
- Multiline On
- Parser_Firstline log_date
- Parser_1 log_attributes
和 Fluentd 類似，Parser_Firstline 參數指定了與多行日志開頭相匹配的解析器的名稱，當然我們也可以包含額外的解析器來進一步結構化你的日志。這里我們配置了首先使用 Parser_Firstline 參數來匹配 ISO8601 日期開頭的日志行，然后使用 Parser_1 參數來指定匹配模式，以匹配日志消息的其余部分，并為它們分配了 timestamp、level、message 標簽。
最終轉換過后我們的日志變成了如下所示的格式：
- {
- "timestamp": "2019-08-01 19:22:14,196",
- "level": "ERROR:",
- "message": "Exception on main handler\nTraceback (most recent call last):\n File \"python-logger.py\", line 9, in make_log\n return word[13]\nIndexError: string index out of range"
- }
