fluentd + Cloud logging(旧:Stackdriver) でファイル名が固定されていないログを処理する-1

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

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

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

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

```bash:/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` までは同じにしないとログを拾わない例になっています。
```
```bash: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 回繰り返す

```bash:~/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
```

### ログディレクトリの準備

```bash
sudo mkdir /var/log/my_custom_app
```

### POSファイルの初期化

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

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

```bash:/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>
```

```bash:~
$ 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
```

連携されました。ファイルへの出力順にならないのは、後ほど説明します。
<img width="600" alt="2020-05-05 105728.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/598801/a22961de-c0be-e531-952a-d757a5842643.png">

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

```bash:/var/log/my_custom_app/
/var/log/my_custom_app/
├── my_app1_20200505020259.log
└── my_app2_20200505020259.log
```

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

```bash:/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 秒以上更新しなかったファイルは追跡対象から外してみましょう。

```bash:/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>
```

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

```bash:
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
```

```bash:~
$ 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` ファイルに登録されています。

```bash:/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)` となっています。

```bash:/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プラグインの動作について理解する](https://debug-life.net/entry/996#tail_Input_Plugin-2)

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

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

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

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