はじめに

前回、fluentd を利用して複数行のログを処理する方を記載しました。
https://qiita.com/ys_nishida/items/f33b7dad5f49650037cc

今回は、ファイル名が固定されていないログファイルに対する処理を記載していこうと思います。

対象のログ

時間単位でログローテートされる
ファイル名にログの作成日時が付与される

というログを考えます。なので、例えば以下の様なファイル構成をターゲットに考えます。

/var/log/my_custom_app/

/var/log/my_custom_app/
├── my_app1_20200504124218.log
├── my_app1_20200504124303.log
├── my_app1_20200504140526.log
├── my_app2_20200504110426.log
└── my_app2_20200504124222.log
# ログファイルが動的に出力される形式なら基本は何でも良いです。
# 本記事では、`my_app` までは同じにしないとログを拾わない例になっています。

my_app1_%Y%m%d%H%M%S.log

2020-05-04 12:42:18.223 test-google-fluentd [ERROR] : test log
# こちらは何でも良いです。

各種準備

テスト用のログ出力スクリプト

ログ作成のスクリプトは、以下の様にします。

scriptの実行時の時間をファイル名につける
application の名前を引数につける
1sec毎にログを出力。
5 回繰り返す

~/my_logger.sh

#!/bin/sh
  
if [[ $# != 1 ]]; then
  echo Usage: sh my_logger.sh [applicationname]
  exit 1
fi

#APP_NAME="my_app1"
APP_NAME=$1
NOWTIME=`date +"%Y%m%d%H%M%S"`
FILENAME="/var/log/my_custom_app/"${APP_NAME}"_"${NOWTIME}".log"

DATETIME=""
HOSTNAME=`hostname`

touch ${FILENAME}

for ii in `seq 5`
do
  DATETIME=`date +"%Y-%m-%d %H:%M:%S.%3N"`
  echo "${DATETIME} ${HOSTNAME} ${APP_NAME} [ERROR] : test log ${ii}" | tee -a ${FILENAME}
  sleep 1
done

ログディレクトリの準備

sudo mkdir /var/log/my_custom_app

POSファイルの初期化

sudo cp /dev/null /var/lib/google-fluentd/pos/my_custom_app.pos

fluentd の設定

それではファイル名が固定されていないログを処理する設定をしましょう。

/etc/google-fluentd/config.d/my_custom_app.conf

<source>
  @type tail
  format none
  path /var/log/my_custom_app/my_app*.log # ← * で動的ファイルを指定
  pos_file /var/lib/google-fluentd/pos/my_custom_app.pos
  read_from_head true
  tag "#{Socket.gethostname}.log"
</source>

~

$ sudo systemctl restart google-fluentd
$ sudo sh my_logger.sh my_app1 & sudo sh my_logger.sh my_app2
2020-05-05 02:02:59.351 test-google-fluentd my_app1 [ERROR] : test log 1
2020-05-05 02:02:59.352 test-google-fluentd my_app2 [ERROR] : test log 1
2020-05-05 02:03:00.357 test-google-fluentd my_app1 [ERROR] : test log 2
2020-05-05 02:03:00.360 test-google-fluentd my_app2 [ERROR] : test log 2
2020-05-05 02:03:01.362 test-google-fluentd my_app1 [ERROR] : test log 3
2020-05-05 02:03:01.366 test-google-fluentd my_app2 [ERROR] : test log 3
2020-05-05 02:03:02.367 test-google-fluentd my_app1 [ERROR] : test log 4
2020-05-05 02:03:02.370 test-google-fluentd my_app2 [ERROR] : test log 4
2020-05-05 02:03:03.370 test-google-fluentd my_app1 [ERROR] : test log 5
2020-05-05 02:03:03.374 test-google-fluentd my_app2 [ERROR] : test log 5

連携されました。ファイルへの出力順にならないのは、後ほど説明します。

log は以下の様になっています。

/var/log/my_custom_app/

/var/log/my_custom_app/
├── my_app1_20200505020259.log
└── my_app2_20200505020259.log

本題の pos ファイルは以下です。

/var/lib/google-fluentd/pos/my_custom_app.pos

/var/log/my_custom_app/my_app1_20200505020259.log       000000000000016d        00000000001ad29f
/var/log/my_custom_app/my_app2_20200505020259.log       000000000000016d        00000000001ad2a1

真ん中の 000000000000016d が読み込んだバイト位置を示しています。
ファイル名が固定されていない場合 pos ファイルの中も自動的に対象ログがエントリ（watch）される仕組みになっています。
右の数値は inode と呼ばれるログの管理番号です。ログがローテートされるタイミングで変わります。が、本記事では新しいログファイルが作られるユースケースを対象にしているので、説明は省きます。

更新していないファイルは追跡対象から外す（unwatch する）

設定方法・動作検証

新しいログファイルを自動的に追跡するのは良いですが、逆に増えれば増えるほど追跡対象が多くなり、サーバの処理性能を圧迫する事になります。そこで重要なのが、limit_recently_modified というパラメータです。
例として、60 秒以上更新しなかったファイルは追跡対象から外してみましょう。

/etc/google-fluentd/config.d/my_custom_app.conf

<source>
  @type tail
  format none
  path /var/log/my_custom_app/my_app*.log # ← * で動的ファイルを指定
  pos_file /var/lib/google-fluentd/pos/my_custom_app.pos
  limit_recently_modified 60s # 60s以上更新がないファイルはfluentdの追跡対象から外す。posをunwatchに変更
  refresh_interval        60s # defaultが60s。説明用に明示的に記
  read_from_head true
  tag "#{Socket.gethostname}.log"
</source>

前の結果を消して、綺麗にして、再度実行します。

sudo systemctl stop google-fluentd
sudo cp /dev/null /var/lib/google-fluentd/pos/my_custom_app.pos
sudo rm -f /var/log/my_custom_app*.log
sudo systemctl start google-fluentd

~

$ sudo sh my_logger.sh my_app1 & sudo sh my_logger.sh my_app2
2020-05-05 10:09:41.734 test-google-fluentd my_app2 [ERROR] : test log 1
2020-05-05 10:09:41.735 test-google-fluentd my_app1 [ERROR] : test log 1
2020-05-05 10:09:42.742 test-google-fluentd my_app2 [ERROR] : test log 2
2020-05-05 10:09:42.744 test-google-fluentd my_app1 [ERROR] : test log 2
2020-05-05 10:09:43.749 test-google-fluentd my_app2 [ERROR] : test log 3
2020-05-05 10:09:43.752 test-google-fluentd my_app1 [ERROR] : test log 3
2020-05-05 10:09:44.754 test-google-fluentd my_app2 [ERROR] : test log 4
2020-05-05 10:09:44.757 test-google-fluentd my_app1 [ERROR] : test log 4
2020-05-05 10:09:45.760 test-google-fluentd my_app2 [ERROR] : test log 5
2020-05-05 10:09:45.763 test-google-fluentd my_app1 [ERROR] : test log 5

まずは通常通り、pos ファイルに登録されています。

/var/lib/google-fluentd/pos

# date
Tue May  5 10:10:35 UTC 2020
# cat my_custom_app.pos 
/var/log/my_custom_app/my_app2_20200505100941.log       000000000000016d        00000000001ad2b3
/var/log/my_custom_app/my_app1_20200505100941.log       000000000000016d        00000000001ad2b4

2分程度経過してからもう一度見ると、unwatch(ffffffffffffffff) となっています。

/var/lib/google-fluentd/pos

# date
Tue May  5 10:12:10 UTC 2020
# cat my_custom_app.pos 
/var/log/my_custom_app/my_app2_20200505100941.log       ffffffffffffffff        00000000001ad2b3
/var/log/my_custom_app/my_app1_20200505100941.log       ffffffffffffffff        00000000001ad2b4

動作原理

それほど複雑ではないですが、以下の動作をしています。

refresh_intervalの時間毎にログファイルをwatchしている。
そのタイミングで、新しいファイルがあれば追跡対象に追加する。
既存のログに対してもこのタイミングでスキャンされる。
- 先ほどのログの出力順と、Cloud logging に連携された順番が変わるのはそのため。
limit_recently_modified よりも古い更新日付を持つファイルは unwatch にする。

こちらの記事を参考にしています。
fluentdのin_tailプラグインの動作について理解する

今回は検証用なので、60s にしましたが、基本は日時単位でログが出来るのが多いでしょうから、余裕をもって 2d とか 3d にするのが良いかと思います。

終わりに

ファイル名が固定されていないログの処理に関して、簡単に検証しました。
ただ、まだ課題が残っています。

pos ファイルにunwatchのログエントリが延々と残ってしまい、posファイルが肥大化する
処理しているファイル名をタグやラベルに追加する

次回はこれらについて記載します。動的に作られるログファイルの処理は、次回と今回の内容のセットで大体OKです。
https://qiita.com/ys_nishida/items/357ecd5a8247b799d43c