More than 3 years have passed since last update.

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

Last updated at 2020-04-11Posted at 2020-04-11

#前回の記事
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ログとして扱う定義を書く
本来なら、正規表現をきちんと記述した方が良いんですが、可読性向上のため、少し雑に書きます。

/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>

touch /var/lib/google-fluentd/pos/my_custom_app_2.pos

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

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

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

sudo sh my_logger2.sh

ログが出力されます。

/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 を見てみます。

INFOのログは1行で、WARNINGのログは数行で、1つずつ来ている事がわかります。
また、前回と異なる点は、今回は明確にログの中からtimestampを拾ってきているところです。
なので、前回はログ内の時刻 ≒ Cloud loggingのtimestampでしたが、今回はログ内の時刻＝Cloud logging のtimestampになっています。
ちなみに、上記で指定したtime_formatですが、詳細はこちらです。

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

/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>

sudo sh my_logger2.sh

出力されるログは先ほどと全く一緒です。
Cloud logging を見てみます。

ホスト名が出力されました。また、上の例と比較するとわかりますが、

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

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

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

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

You get articles that match your needs
You can efficiently read back useful information
You can use dark theme

What you can do with signing up