⏱️

そのプロセス停止ちょっと待って！ FireLensでログ欠損を防ぐための待ち時間設定

2025/01/06に公開

AWS

はじめに

AWS ECS Fargateでコンテナを運用する際、ログ収集に FireLens (Fluent Bit) を使用するのは一般的な構成です。
しかし、コンテナの停止時に末尾のログが欠損する問題に遭遇したことはありませんか？
これは、プロセスの停止とログの転送のタイミングが適切に制御されていないことが原因です。
この記事では、その原因と対策について解説します。

想定読者

AWS ECS Fargate + FireLens (Fluent Bit) の構成でログ欠損が発生している
特にアプリケーションのプロセス終了間際のログが欠損する

TL;DR

ECS Fargate + FireLens (Fluent Bit) の構成でアプリケーションのプロセス停止直前に出力されたログの欠損を防ぐには、アプリケーションのプロセス停止前に適切な待ち時間が必要
必要に応じて Fluent Bit の Grace Period も調整する

前提条件など

ECS Fargate で稼働しているアプリケーションのログ転送に FireLens (Fluent Bit) によるサイドカーコンテナを利用している
Fluent Bit v1.9.10, またはそれ相当のバージョンを使用しているログ転送コンテナイメージ
- amazon/aws-for-fluent-bit:2.32.2.20240516
- newrelic/logging-firelens-fluentbit:2.0.0

実際にトラブルシューティングした構成

ECS run-task によって起動されるシンプルなバッチ処理
- ECS サービスで構成される Web サーバーなどではこの問題はあまり顕在化しない
  - 停止前にトラフィックの draining が行われ、ほとんどの場合で必要なログの転送が終わった状態でコンテナが停止するため
  - ただし、この場合でもプロセス停止処理のログが欠損することはある
アプリケーションは Go で実装
ロギングライブラリは zerolog
Fluent Bit から New Relic に直接ログ転送
ログ転送コンテナイメージは newrelic/logging-firelens-fluentbit:2.1.0

末尾のログが欠損する問題とは

正常な場合

問題が発生している場合

問題が発生するシナリオ

アプリケーションプロセスが終了間際にログを出力し、即座にプロセス停止
ログは一旦 ECS 基板上の Unix domain socket にバッファされる
ECS がアプリケーションプロセスの停止を検知
ECS がコンテナ停止シグナル（SIGTERM）をタスクに含まれる他のコンテナ (FluentBit など) に送信
SIGTERM を受信した FluentBit は Grace モードに移行し、Unix domain socket にバッファされているログの読み取りを停止
FluentBit が読み取る前のログが Unix domain socket に残っているものの、FluentBit が読み取りを停止したため、転送されずにログが欠損する

シーケンス図による説明

Fluent Bit のログから問題を説明する

前準備: Fluent Bit のデバッグログを有効にする

{
  "containerDefinitions": [
    {
      "name": "log_router",
      "image": "533243300146.dkr.ecr.ap-northeast-1.amazonaws.com/newrelic/logging-firelens-fluentbit:2.1.0",
      "environment": [
        {
          "name": "FLB_LOG_LEVEL",
          "value": "debug"
        }
      ]
    }
  ]
}

Fluent Bit のデバッグログを有効にすることで、ログの転送がどのように行われているかの詳細を確認できます。

解決策：プロセス停止の待ち時間を設定する

1. アプリケーション側での対応

アプリケーションでプロセス終了直前の待ち時間を導入します。
これは Go 言語特有の話ですが、panic をカバーするため defer で recover しつつ、待ち時間の処理を実行しています。

package main

import (
	"os"
	"time"

	"github.com/rs/zerolog/log"
)

func main() {
	var err error

	defer func() {
		// declare var because it should be panicked again after recovered.
		var r any

		if r = recover(); r != nil {
			recoverErr, ok := r.(error)
			if ok {
				log.Error().Err(recoverErr).Msg("panic occurred")
			} else {
				// logging non-error panic, typically string
				log.Error().Msgf("panic occurred: %s", r)
			}
		}

		const waitingForShutdown = 3 * time.Second

		log.Debug().Msgf("waiting for shutdown %s...", waitingForShutdown)
		time.Sleep(waitingForShutdown)

		if err != nil {
			os.Exit(1)
		}

		if r != nil {
			panic(r)
		}
	}()

	if err = run(os.Args); err != nil {
		log.Error().Err(err).Send()
	}
}

2. FluentBit の Grace Period 設定

FluentBitには、シャットダウン時にバッファされたログを転送するための待機時間を設定できます。これはGraceパラメータで制御します：

[SERVICE]
    Flush 1
    Grace 30

この設定の根拠は、AWSの公式ブログ記事「詳解 FireLens – Amazon ECS タスクで高度なログルーティングを実現する機能を深く知る ^[1]」で説明されています。

パラメータ	設定値	説明
Flush	1	バッファのフラッシュ間隔を1秒に設定することで、ログの転送遅延を最小限に抑えます
Grace	30	シャットダウン時に30秒の猶予を設定することで、バッファされたログを確実に転送する時間を確保します

これらの設定により、コンテナ停止時のログ欠損リスクを大幅に低減できます。特に Grace 30 の設定は、リトライ可能な転送エラーが発生した場合のリトライ待機時間を十分に確保できます。リトライしきれずログ欠損が発生していることが多い場合は、この Grace の設定を検討してください。

FluentBit設定の上書き方法

FireLens は、簡単に言うと ECS タスク定義で FluentBit の設定ファイルを生成・上書きすることができる仕組みです。これによって、ECS タスク定義で FluentBit の設定を上書きすることができます。

{
  "containerDefinitions": [
    {
      "name": "log_router",
      "image": "533243300146.dkr.ecr.ap-northeast-1.amazonaws.com/newrelic/logging-firelens-fluentbit:2.1.0",
      "firelensConfiguration": {
        "type": "fluentbit",
        "options": {
          "config-file-type": "file",
          "config-file-value": "/fluent-bit/configs/minimize-log-loss.conf"
        }
      }
    }
  ]
}

効果の確認方法

Fluent Bit のログの確認

Fluent Bit のログを確認することで、Fluent Bit のログ読み取りと SIGTERM 受信、Graceful shutdown モードに入るタイミングを確認できます。

New Relic のダッシュボードによる定量的な確認

単純な方法として、アプリケーションの開始・終了時のログの数の差分を確認します。
今回は New Relic に転送したログの欠損の確認のため、 NRQL でダッシュボードを構築してみました。

ダッシュボードの構築

ログ欠損率の NRQL クエリ

ECS クラスター名を変数にすることで、複数の ECS クラスターで同じダッシュボードを利用できます。

SELECT 
  (filter(count(*), WHERE message = 'batch started') - filter(count(*), WHERE message = 'batch finished')) / filter(count(*), WHERE message = 'batch started') AS 'missing ratio(%)'
FROM Log
WHERE
  ecs_cluster = {{ecs_cluster}}
TIMESERIES AUTO

開始・終了ログ数の NRQL クエリ

同時に別のクエリで単純なログの数も出力しておくことで、異常値の確認もできるようにします。

SELECT
  filter(count(*), WHERE message = 'batch started') AS 'start logs(count)',
  filter(count(*), WHERE message = 'batch finished') AS 'end logs(count)'
FROM Log
WHERE ecs_cluster = {{ecs_cluster}}
TIMESERIES AUTO

計測に用いるアプリケーション共通の開始・終了ログの実装

アプリケーションでは urfave/cli/v2 ^[4] を使用しているため、コマンドの Before と After を利用してコマンドの前処理と後処理でアプリケーション共通のログを出力させました。

package main

import (
	"github.com/cockroachdb/errors"
	"github.com/rs/zerolog/log"
	"github.com/urfave/cli/v2"
)

func run(args []string) error {
	app := cli.NewApp()
 	app.Command = []*cli.Command{
		// コマンド定義
	}

	app.Before = func(ctx *cli.Context) error {
		log.Ctx(ctx.Context).Debug().Msg("batch started")

		return nil
	}

	app.After = func(ctx *cli.Context) error {
		log.Ctx(ctx.Context).Debug().Msg("batch finished")

		return nil
	}

  	if err := app.Run(args); err != nil {
		return errors.Wrap(err, "コマンドの実行に失敗しました")
	}

	return nil
}

ログ欠損の改善結果確認

先に示したダッシュボードのスクリーンショットのグラフの通り、対策をリリースした 12/11 以降からログ欠損率が大幅に改善しています。
改善前は 10% 近い割合でログ欠損が発生していましたが、改善後は 0.1% 未満に改善しました。

改善のリリース以降から1ヶ月弱たった現在では、全体で 0.013% のログ欠損率となっています。

一方で、バッチ処理の種類によってはログ欠損率が高いものが確認されており、これは別途対策を検討しています。

少し調査したところ、これらは Fluent Bit から New Relic へ転送するところでエラーが発生していることがわかりました。
とはいえ、根本的にログ転送のエラーを 0% にすることは不可能です。別のプラットフォーム (例えば AWS なら CloudWatch Logs や S3 など) に別途ログを転送することで、万が一のログ欠損時にリカバリすることを考えています。

まとめ

ECS Fargate + FireLens (Fluent Bit) の構成でアプリケーションのプロセス停止直前に出力されたログの欠損を防ぐには、アプリケーションのプロセス停止前に適切な待ち時間が必要
必要に応じて Fluent Bit の Grace Period も調整する

参考

脚注