FireLens(Fluent Bit)からCloudWatch Logsへログを送信時、ThrottlingExceptionエラー回避のためログストリーム設定を見直す

FireLensで起動するFluent BitからCloudWatch Logsへ送信するときはログストリームを個別に作成するようにしよう。
2021.08.11

Fargateで起動するFireLens(Fluent Bit)のログルーティングでCloudWatch Logsへの送信設定を検証していました。負荷試験時にFireLensコンテナのログにスロットリングエラーのログが記録されました。

本記事ではFluent Bitの設定を見直す箇所、CloudWatch LogsのAPIレート制限についてみていきます。

Error Message

[error] [output:cloudwatch_logs:cloudwatch_logs.0] PutLogEvents API responded with error='ThrottlingException', message='Rate exceeded for logStreamName webapp'
[error] [output:cloudwatch_logs:cloudwatch_logs.0] Failed to send log events
[error] [output:cloudwatch_logs:cloudwatch_logs.0] Failed to send events
[ warn] [engine] failed to flush chunk '1-1628656770.31314631.flb', retry in 9 seconds: task_id=1, input=forward.1 > output=cloudwatch_logs.0 (out_id=0)

Fluent BitはCloudWatch Logsへ再送を試みているログも確認できます。いずれCloudWatch Logsへ送信できる可能性はあります。しかし、CloudWatch Logsへ送り終わる前にコンテナが停止すると、コンテナ内に保持していたログと共に失います。できれば避けたいです。

結論

今回の原因は単一のログストリームにログを保存していました。ログストリーム単位の制限値を超過しやすい環境にありました。

  • CloudWatch LogsのPutLogEvents APIのクォータはログストリーム単位である
  • Fluent Bitの設定でコンテナごとに個別のログストリームを作成して保存する
  • 個別のログストリーム作成にはECSメタデータの変数を利用すると簡単

設定例

ログストリーム名はwebapp-の後にFireLensが起動したタスクのIDを付与

extra.conf抜粋

[OUTPUT]
    Name   cloudwatch
    Match webapp-firelens*
    region ap-northeast-1
    log_group_name /ecs/logs/variable-test
    log_stream_name webapp-$(ecs_task_id)  <- ECSメタデータ変数を利用してタスクIDごとのログストリームを作成する
    auto_create_group true

実行結果

検証環境

項目 バージョン
aws-for-fluent-bit 2.19.0
Fluent Bit 1.8.3
Fargate platform 1.4.0

CloudWatch Logsを知る

エラーメッセージ内のキーワードを個別に確認します。

PutLogEvents APIとは

CloudWatch LogsのログストリームにログイベントをアップロードできるAPIです。

Fluent BitからCloudWatch Logsへログを送るのに利用されていました。

ThrottelingException Rate exceededとは

一定時間内に受信可能なAPIリクエスト数を制限しています。その制限値を超過したことを示しています。 一般的にスロットリングエラーを回避するには、APIリクエスト頻度を減らす、APIリクエストの間隔をずらす(同時実行数を減らす)、いい感じの間隔で再試行する(Exponential Backoff)などがあげられます。

今回はどこの制限値を超過してしまったのでしょうか?

CloudWatch Logsのクォータ確認

PutLogEventsリソースのクォータを確認します。2020/8/10現在

  • ログストリームごとに1秒間5リクエスト
  • リクエストの最大サイズは1MB
  • アカウントのリージョンごとに1秒間800トランザクション
    • 一部対象外のリージョンあり、1500トランザクション/秒

CloudWatch Logs quotas - Amazon CloudWatch Logs

ログストリーム名webappに対してとメッセージに書いてあり、1秒間5リクエストの制限値を超過した可能性が非常に高いです。復数のFluent Bitから単一のログストリームを指定している状況でした。FireLnesコンテナとログストリームが1対多の関係です。

ログストリーム単位のメトリクスは確認できませんでしたが、ロググループ単位のIncommingLogEventsを確認できました。青い線がアプリケーションコンテナのログイベントで、オレンジ色の線がFireLensコンテナのログイベントです。青い線が値を確認すると桁違いにログイベントが発生していることがわかります。これが単一のログストリームに向いている状況です。

問題のあったFluent Bitの設定

log_stream_namewebappと指定しています。

extra.conf

[SERVICE]
    Flush 1
    Grace 30

[FILTER]
    Name grep
    Match webapp-firelens*
    Exclude log ^(?=.*ELB-HealthChecker\/2\.0).*$

[OUTPUT]
    Name   cloudwatch
    Match webapp-firelens*
    region ap-northeast-1
    log_group_name /ecs/logs/variable-test
    log_stream_name webapp
    auto_create_group true

上記設定ですとロググループ名はlog_group_nameで指定した/ecs/logs/variable-testが作成されます。

ログストリームはwebappが1個作成されています。

単一のログストリームに対して復数のFireLens(Fluent Bit)コンテナからPutLogEvents APIのリクエストが発生します。Flush1秒指定であることもあり、秒間5リクエスト制限は容易に超過しそうです。

Fluent Bitの設定を見直す

FireLens(Fluent Bit)コンテナごとのlog_stream_nameユニークな名前付けて作成したいです。FireLensコンテナとログストリームが1対1の関係にしログの送信先を分散させます。

aws-for-fluent-bitイメージをECSで実行する場合、ECSのメタデータを利用した変数が用意されています。タスクIDが格納されている変数$(ecs_task_id)を利用してlog_stream_nameを設定します。

extra.conf

[SERVICE]
    Flush 1
    Grace 30

[FILTER]
    Name grep
    Match webapp-firelens*
    Exclude log ^(?=.*ELB-HealthChecker\/2\.0).*$

[OUTPUT]
    Name   cloudwatch
    Match webapp-firelens*
    region ap-northeast-1
    log_group_name /ecs/logs/variable-test
    log_stream_name webapp-$(ecs_task_id)
    auto_create_group true

実行結果

タスクID付きのログストリーム名が作成されるようになりました。タスクごとにログストリームが増えるため、スケールアウトすればその分だけ新しいログストリームが追加されます。

FireLensのログを確認すると、Fluent Bit起動時にタスクIDを付きのログストリーム作成している様子が確認できます。

変数に格納されていたECSメタデータはどこから?

FireLensのコンテナにECS Execして確認してみます。環境変数の中からタスクIDの値は確認できませんでした。

環境変数

HOSTNAME=ip-10-0-17-186.ap-northeast-1.compute.internal
TERM=xterm-256color
AWS_CONTAINER_CREDENTIALS_RELATIVE_URI=/v2/credentials/2b568cca-f442-4b52-8e09-30d04887980c
AWS_EXECUTION_ENV=AWS_ECS_FARGATE
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
AWS_DEFAULT_REGION=ap-northeast-1
PWD=/
LANG=C.UTF-8
AWS_REGION=ap-northeast-1
SHLVL=1
HOME=/root
ECS_CONTAINER_METADATA_URI=http://169.254.170.2/v3/1eade9f9a747448897e7970b8026f77b-1714341083
ECS_CONTAINER_METADATA_URI_V4=http://169.254.170.2/v4/1eade9f9a747448897e7970b8026f77b-1714341083
_=/usr/bin/env

ECS_CONTAINER_METADATA_URIがあったので、curlでアクセスしてみて何の値を取得できるのか確認します。

ECS_CONTAINER_METADATA_URI

curl http://169.254.170.2/v3/1eade9f9a747448897e7970b8026f77b-1714341083

com.amazonaws.ecs.task-arnからタスクIDを取得できますね。その他にはクラスター名をcom.amazonaws.ecs.clusterから取得できますね。

実行結果

{
	"DockerId": "1eade9f9a747448897e7970b8026f77b-1714341083",
	"Name": "log_router",
	"DockerName": "log_router",
	"Image": "123456789012.dkr.ecr.ap-northeast-1.amazonaws.com/sample-custom-logrouter-firelens:6b1d27f",
	"ImageID": "sha256:b5a9487fead1c815c2bcb8061d8d4003dab0dbbdd37416802b492c0cac48386e",
	"Labels": {
		"com.amazonaws.ecs.cluster": "arn:aws:ecs:ap-northeast-1:123456789012:cluster/sample-dev-cluster",
		"com.amazonaws.ecs.container-name": "log_router",
		"com.amazonaws.ecs.task-arn": "arn:aws:ecs:ap-northeast-1:123456789012:task/sample-dev-cluster/1eade9f9a747448897e7970b8026f77b",
		"com.amazonaws.ecs.task-definition-family": "sample-dev-webapp-taskdefinition",
		"com.amazonaws.ecs.task-definition-version": "12"
	},
	"DesiredStatus": "RUNNING",
	"KnownStatus": "RUNNING",
	"Limits": {
		"CPU": 2
	},
	"CreatedAt": "2021-08-09T14:06:30.976767663Z",
	"StartedAt": "2021-08-09T14:06:30.976767663Z",
	"Type": "NORMAL",
	"Networks": [
		{
			"NetworkMode": "awsvpc",
			"IPv4Addresses": [
				"10.0.17.186"
			]
		}
	]
}

興味本位で覗いてみた結果、このメタデータから取得した値を利用しているのではないかと思いました。

まとめ

今回の原因は単一ログストリームに復数のFluet Bitからログを送信したためによるものでした。ユニークなログストリーム名を作成するにはFluent Bit設定ファイルでECSメタデータの変数を利用すると手軽です。${ecs_task_id}の他に使えそうな変数として$(uuid)があります。こちらはランダムな英数字を返してくれます。どちらかというとタスクIDの方がタスクに紐付いたログの保存先だと判別しやすいので使いやすいです。

補足

FireLensコンテナ自身のログをCloudWatch Logs(ログドライバー:awslogs指定)へ保存した場合、デフォルト設定でログストリーム名にタスクIDが付与されて作成されます。詳しくは以下のリンクを参照ください。

ECSメタデータの変数は旧プラグインのみ利用できます。詳しく以下のリンクを参照ください。

おわりに

Flush1秒を伸ばしてPutLogEvents APIをリクエスト頻度を下げるのも手です。副作用としてはFireLensコンテナ内でログを保持している時間が長くなります。コンテナ停止した際にログを失う量も増える可能性はあります。FireLensコンテナ内にログを溜め込まずCloudWatch Logsへ早めに送り永続化してほしくなります。

参考