fluentd + Cloud logging(旧:Stackdriver)で複数行のログを処理する

#前回の記事
https://qiita.com/ys_nishida/items/bf04fa54ab53e0369806
前回、fluentd を利用してログにフィルタをかけたり加工したりしました。
基本的に1行形式のログを処理してきましたが、今回は複数行のログを処理してみようと思います。

#対象のログ
複数行出力され、かつ形式が一定のログなら何でも良いんですが、とりあえず手元にあった Jenkins の`docker logs`を対象にしてみます。

```
2020-03-03 13:18:32.374+0000 [id=24]	INFO	hudson.model.UpdateSite#getJSONObject: Loaded and parsed /var/jenkins_home/updates/default.json in 14.0s
2020-03-03 14:34:15.645+0000 [id=12]	WARNING	o.e.j.s.h.ContextHandler$Context#log: Error while serving http://10.0.0.1:8080/job/test-job1/build
javax.servlet.ServletException: This page expects a form submission but had only {payload=[{"ref":"refs/heads/master","before":"345f12ef12525f51a99a2ca1b9696c5ff6b4bdc9","after":"e3364ff307bc61a591a565a74e36e54ae9a4fceb"}
	at jenkins.model.ParameterizedJobMixIn.doBuild(ParameterizedJobMixIn.java:211)
Caused: java.lang.reflect.InvocationTargetException
	at java.lang.Thread.run(Thread.java:748)
```
ちなみに、GithubからWebhookを投げた際、パラメータが不正だった時にJenkinsが吐いたログの抜粋です。

#複数行を1ログとして扱う定義を書く
本来なら、正規表現をきちんと記述した方が良いんですが、可読性向上のため、少し雑に書きます。

```bash:/etc/google-fluentd/config.d/my_custom_app_2.conf
<source>
  @type tail
  <parse>
    @type multiline
    format_firstline /^\d{4}-\d{2}-\d{2}.+(INFO|WARNING|ERROR)/
    format1 /^(?<time>\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}.\d{3}\+\d{4})(?<message>.*)/
    time_format %Y-%m-%d %H:%M:%S.%L%z
  </parse>
  path /var/log/my_custom_app_2.log
  pos_file /var/lib/google-fluentd/pos/my_custom_app_2.pos
  multiline_flush_interval 3s # firstlineが来ない場合、3秒待つ
  read_from_head true
  tag my_custom_app_log_2
</source>
```
```bash:
touch /var/lib/google-fluentd/pos/my_custom_app_2.pos
```

- `format_firstline`は、ログの最初の行に合致する正規表現
    - 例は少し雑ですが、本来は`.`とかは使わず極力厳密に記述した方が良い
- `format1`が**firstlineを含むログ全体の定義**
    - **ラベルを指定しないとエラーで起動しないので注意！**
    - 2行目、3行目など、複数の行に渡ってラベルを指定したい場合は`format2`,`format3`と続ける。[公式サイトの例](https://docs.fluentd.org/parser/multiline#rails-log)

さて、それではログを投げてみましょう。
少し適当ではありますが、ログを出力するシェルを用意します。時刻以外はただechoするだけ…

```bash:my_logger2.sh 
#!/bin/sh
datetime=`date +"%Y-%m-%d %H:%M:%S.%3N"`
echo "${datetime}+0000 [id=24]    INFO    hudson.model.UpdateSite#getJSONObject: Loaded and parsed /var/jenkins_home/updates/default.json in 14.0s" >> /var/log/my_custom_app_2.log
echo "${datetime}+0000 [id=12]    WARNING o.e.j.s.h.ContextHandler$Context#log: Error while serving http://10.0.0.1:8080/job/test-job1/build" >> /var/log/my_custom_app_2.log
echo 'javax.servlet.ServletException: This page expects a form submission but had only {payload=[{"ref":"refs/heads/master","before":"345f12ef12525f51a99a2ca1b9696c5ff6b4bdc9","after":"e3364ff30
7bc61a591a565a74e36e54ae9a4fceb"}' >> /var/log/my_custom_app_2.log
echo "    at jenkins.model.ParameterizedJobMixIn.doBuild(ParameterizedJobMixIn.java:211)" >> /var/log/my_custom_app_2.log
echo "Caused: java.lang.reflect.InvocationTargetException" >> /var/log/my_custom_app_2.log
echo "    at java.lang.Thread.run(Thread.java:748)" >> /var/log/my_custom_app_2.log
```
```bash
sudo sh my_logger2.sh
```

ログが出力されます。

```bash:/var/log/my_custom_app_2.log
2020-04-11 12:57:25.895+0000 [id=24]    INFO    hudson.model.UpdateSite#getJSONObject: Loaded and parsed /var/jenkins_home/updates/default.json in 14.0s
2020-04-11 12:57:25.895+0000 [id=12]    WARNING o.e.j.s.h.ContextHandler#log: Error while serving http://10.0.0.1:8080/job/test-job1/build
javax.servlet.ServletException: This page expects a form submission but had only {payload=[{"ref":"refs/heads/master","before":"345f12ef12525f51a99a2ca1b9696c5ff6b4bdc9","after":"e3364ff307bc61a591a565a74e36e54ae9a4fceb"}
    at jenkins.model.ParameterizedJobMixIn.doBuild(ParameterizedJobMixIn.java:211)
Caused: java.lang.reflect.InvocationTargetException
    at java.lang.Thread.run(Thread.java:748)
```

Cloud logging を見てみます。
![cloud logging 0.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/598801/cd474b31-e168-bcc7-3185-294f87253a00.png)
INFOのログは1行で、WARNINGのログは数行で、1つずつ来ている事がわかります。
また、[前回](https://qiita.com/ys_nishida/items/8b5274d8f3ec740ffa16)と異なる点は、今回は明確にログの中から`timestamp`を拾ってきているところです。
なので、[前回](https://qiita.com/ys_nishida/items/8b5274d8f3ec740ffa16)は**ログ内の時刻 ≒ Cloud loggingのtimestamp**でしたが、今回は**ログ内の時刻＝Cloud logging のtimestamp**になっています。
ちなみに、上記で指定した`time_format`ですが、詳細は[こちら](https://docs.ruby-lang.org/en/2.4.0/Time.html#method-i-strftime)です。

#fluentdで新しくラベルを付ける
ついでですが、本記事の例に出したログはホスト名の情報が記述されていないので、それをfluentdに付与してもらいましょう。

```bash:/etc/google-fluentd/config.d/my_custom_app_2.conf
<source>
  @type tail
  <parse>
    @type multiline
    format_firstline /^\d{4}-\d{2}-\d{2}.+(INFO|WARNING|ERROR)/
    format1 /^(?<time>\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}.\d{3}\+\d{4})(?<message>.*)/
    time_format %Y-%m-%d %H:%M:%S.%L%z
  </parse>
  path /var/log/my_custom_app_2.log
  pos_file /var/lib/google-fluentd/pos/my_custom_app_2.pos
  multiline_flush_interval 3s # firstlineが来ない場合、3秒待つ
  read_from_head true
  tag my_custom_app_log_2
</source>

<filter my_custom_app_log_2>
  @type record_transformer
  <record>
    hostname "#{Socket.gethostname}"
    tag ${tag}
  </record>
</filter>
```
```bash
sudo sh my_logger2.sh
```
出力されるログは先ほどと全く一緒です。
Cloud logging を見てみます。
![cloud logging 1.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/598801/09850dde-968e-3743-27c6-b0062d498dac.png)
ホスト名が出力されました。また、上の例と比較するとわかりますが、

- ラベルが`message`のみ：`textPayload`に出力
- `message`以外もある：`jsonPaylod`に出力

となります。
この`#{Socket.gethostname}`ですが、これはrubyのコードです。そうなんです、`fluentd`は`ruby`で実装されている様です。`"#{ruby_code}"`で記述できます。例えば、`"#{ENV['PATH']}"` で環境変数`${PATH}`が取得できます。
これはこれで長くなるので今回はここまでにします。

#最後に
複数行のログフォーマットは正規表現を間違えたり、意図していないフォーマットのログが書かれたりすると、正規表現のマッチング処理でCPUが100％に張り付いたり、fluentdが起動できない状況を引き起こす事があります。
改行が処理を区切る合図にならないので、`firstline`のマッチングが出来ないようなフォーマットが来ると、ログ全量との正規表現マッチングを始める事になりますので、その点はよく注意して`multiline`の指定を利用してください。

次回は、対象のログファイルを`*`で指定する場合の注意（主にposファイル周り）を掲載しようと考えています。