概要

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

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

何が起こったか

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

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

また、CloudWatch Logs Insightsにて1時間ごとのログ件数を調べると、該当期間のログが数万から10万倍になっていました。

原因と思われるエラー

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ファイル

[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 // 追加

対応の根拠と根本原因

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

[error] [input:tail:tail.0] file=/var/log/hogehoge/stdout.log requires a larger buffer size, lines are too long. Skipping file.が発生したこと
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 としています。

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 はログを最初から収集し直します。

ここでは解決策として、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つあります。

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

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

上記1.2の対応策として、

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

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等を確認して起こりうるエラーを調査しておくなどの対策が必要ですね。