Cloudwatch Logsに吐かれるログを爆増させてしまった話【fluent-bit】

# 概要

先日、以下の記事で紹介したように、fluent-bitを利用して
アプリケーションログをCloudwatch Logsに吐かせる設定を行いました。

https://qiita.com/kotobuki5991/items/d7c7af6840e2491d8e02

しかし、時折Cloudwatch Logsへ異常なほど多いログが吐かれる事態が発生し、コストの上昇を招いてしまいました。
今回は、解決方法と根本原因について説明します。

# 何が起こったか

fluent-bitからCloudwatch Logsへ送信されるアプリケーションログが
2024-04-29 21:03:48から2024-04-30 00:58:48の間急増しました。

![スクリーンショット 2024-07-13 16.55.00.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/2475547/a821a414-6e9c-d613-1cd7-0f74528e5605.png)

fluent-bitのログを確認すると、**requires a larger buffer size, lines are too long. Skipping file**が約1分毎に発生していることが分かりました。

また、[CloudWatch Logs Insights](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatch/latest/logs/AnalyzingLogData.html)にて1時間ごとのログ件数を調べると、該当期間のログが数万から10万倍になっていました。

![スクリーンショット 2024-07-13 16.58.21.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/2475547/bbef9499-dbba-05d9-eebc-7fcc8eac72f6.png)

### 原因と思われるエラー
```
4月 29 21:01:44 appname-01 fluent-bit[9578]: [2024/04/29 21:01:44] [error] [input:tail:tail.0] file=/var/log/hogehoge/stdout.log requires a larger buffer size, lines are too long. Skipping file.
```

# 最終的な対応

該当アプリケーション用のfluent-bit設定ファイルに、以下4つの設定を追加しました。
各設定については後述します。

- confファイル

```conf
[INPUT]
    Name tail 
    Path /var/log/hogehoge/stdout.log
    Tag  hogehoge.log
    Buffer_Chunk_Size 2M // 追加
    Buffer_Max_Size 2M // 追加
    Skip_Long_Lines On // 追加

[OUTPUT]
    name cloudwatch_logs
    match   hogehoge.log
    region ap-northeast-1
    log_group_name /aws/ec2/hogehoge
    log_stream_name ${EC2_TAG_NAME}-${DEPLOY_DATETIME}
    auto_create_group true
    workers 1
    log_retention_days 3
    log_key log
    retry_limit 5 // 追加
```

# 対応の根拠と根本原因

原因は、以下の２点です。

1. **[error] [input:tail:tail.0] file=/var/log/hogehoge/stdout.log requires a larger buffer size, lines are too long. Skipping file.が発生したこと**
2. **1のエラーが発生した時、ログファイル全体がcloudwatch logsに再送されていること**

2が怖すぎますね...
例えば、ログファイルに100万行のログがある状態で1のエラーが発生すると、100万行が全てCloudwatch logsに再送されてしまいます。

## 1の解決策

### Buffer_Chunk_Size、Buffer_Max_Size

このエラーは、ログの1行あたりのbyteが大きすぎると発生します。
関連する設定はBuffer_Chunk_Size、Buffer_Max_Sizeで、これらはデフォルト値である32kbが使用されていました。

| Key | Description | Default |
| ---- | ---- | ---- |
| Buffer_Chunk_Size | ファイルデータを読み込むための初期バッファサイズを設定する。この値はバッファサイズを大きくするために使用される。この値は、https://docs.fluentbit.io/manual/v/dev-2.2/administration/configuring-fluent-bit/unit-sizes の指定に従わなければならない。 | 32k |
| Buffer_Max_Size | 監視ファイルごとのバッファサイズの上限を設定する。バッファを増やす必要がある場合（非常に長い行など）、この値を使用してメモリ・バッファの増加量を制限します。ファイルの読み込みがこの制限を超えると、そのファイルは監視ファイルリストから削除されます。この値はhttps://docs.fluentbit.io/manual/v/dev-2.2/administration/configuring-fluent-bit/unit-sizes の指定に従わなければならない。 | 32k |

エラー発生原因のログは51.091kbであり、32kbを超えており、
```
 [appname@prod] grep "2024-04-29T21:01:44.647987737Z" /var/log/hogehoge/stdout.log | wc -c                                
51091
```
以下のように該当のログを出力する箇所（ここではhogehoge_usecase.goとします）を確認すると、時折32kbを超えることがありました。

```
[appname@prod] $   grep "hogehoge_usecase.go" /var/log/hogehoge/stdout.log | while read -r line || [ -n "${line}" ]; do                                                     
    byte_count=$(echo -n "$line" | wc -c)
    if (( byte_count > 32000 )); then
        echo -n "$byte_count"
       echo "\n"
    fi
done
49852

49851

49852

49852

50009
```


そこで以下のIssueと、上記のbyte数を参考に、Buffer_Chunk_SizeおよびBuffer_Max_Sizeを2MBに設定しました。

> ログ行が32kbを超える場合は、Buffer_Chunk_Sizeプロパティに従って、希望の値に調整してください： 
> 
> http://fluentbit.io/documentation/0.11/input/tail.html
>
> https://github.com/fluent/fluent-bit/issues/354

### retry_limit

また、エラー時に何度もログが再送されていたことより、リトライ回数に明示的に制限をかけました。

今回はretry_limit 5 としています。

https://docs.fluentbit.io/manual/v/dev-2.2/administration/scheduling-and-retries#configuring-retries

> **Configuring Retries**
スケジューラーにはRetry_Limitという簡単な設定オプションがあり、各出力セクションで個別に設定できる。
このオプションによって、リトライを無効にしたり、リミットを設けてN回トライし、そのリミットに達したらデータを破棄したりすることができる：

|  | Value | Description |
| --- | --- | --- |
| Retry_Limit | N | 再試行の最大回数を設定する整数値。 Nは≧1でなければならない（デフォルト：1）。 |
| Retry_Limit | no_limits or False | Retry_Limitがno_limitsまたはFalseに設定されている場合、スケジューラが実行できる再試行回数に制限がないことを意味する。 |
| Retry_Limit | no_retries | Retry_Limitがno_retriesに設定されている場合、リトライは無効になり、スケジューラは最初の送信が失敗した場合、宛先へのデータ送信を試みない。 |


# 2の解決策

### **Skip_Long_Lines On**

`requires a larger buffer size, lines are too long. Skipping file.` の発生時にfluent-bitがログファイルを最初から読み直す問題は、以下Issueでも報告されています。

**[issue] fluent-bitはmycatのログを収集する。ログが長すぎる場合、fluent-bit はログを最初から収集し直します。**

https://github.com/fluent/fluent-bit/issues/736

**ここでは解決策として、Skip_Long_LinesをOnにすることが挙げられています。**

また、Fluent-bitの開発者は以下のように言及しており、fluent-bitのこの挙動は仕様だと思われます。

> ファイルオフセットが戻らない、つまり前の位置から読み始めない。ノーマルモードとマルチラインモードでテストしました。動作は予想通り。
> 
> 
> 長い行が見つかるとエラーメッセージが表示され、ファイルは監視されなくなる。長い行をスキップして他の行の処理を続けたい場合は、ファイルの入力末尾セクションに 'Skip_Long_Lines On' を追加してください。
> 


# 要約

fluent-bitから送信Cloudwatch Logsへされるアプリケーションログが2024-04-29 21:03:48から2024-04-30 00:58:48の間急増しました。

原因は2つあります。

1. requires a larger buffer size, lines are too long. Skipping file.というエラーがが繰り返し発生したこと。
2. 1のエラー発生時に、fluent-bitによって**ログファイル全体**がcloudwatchへ再送されたこと。

なお、2の挙動は想定通りだとfluent-bit開発者が言及しています。

上記1.2の対応策として、

該当アプリケーション用のfluent-bit設定ファイルに以下４つの設定を追加しました。

- confファイル

```conf
[INPUT]
    Name tail 
    Path /var/log/hogehoge/stdout.log
    Tag  hogehoge.log
    Buffer_Chunk_Size 2M // 追加
    Buffer_Max_Size 2M // 追加
    Skip_Long_Lines On // 追加

[OUTPUT]
    name cloudwatch_logs
    match   hogehoge.log
    region ap-northeast-1
    log_group_name /aws/ec2/hogehoge
    log_stream_name ${EC2_TAG_NAME}-${DEPLOY_DATETIME}
    auto_create_group true
    workers 1
    log_retention_days 3
    log_key log
    retry_limit 5 // 追加
```

# 振り返り

弊社サービスでは、可変長かつ大きめのログが吐かれる箇所が存在しており、設定時にその考慮が不足していました。
その結果、不要なログの再送が発生し、コストの増加を招いてしまいました。

今後は設定漏れ・考慮漏れがないように、issue等を確認して起こりうるエラーを調査しておくなどの対策が必要ですね。