Fluent Bit の「broken connection」を keepalive の設定 1 行で 96% 減らしてみた

こんにちは。製造ビジネステクノロジー部所属の hongkii です。

EKS や ECS で Fluent Bit を運用していると、CloudWatch Logs への送信で broken connection や Failed to send log events といったエラーが出ていることはないでしょうか。

私の EKS 環境でもこのエラーが出続けていて、アラート通知にも流れてきていました。そこで、なぜこのエラーが発生するのかを調べ、原因をなくせないか確かめてみました。

結果として、Fluent Bit の設定を 1 行追加するだけで broken connection が 9 割以上減ったので、その過程をまとめます。

Fluent Bit の cloudwatch_logs 出力に入れる設定なので、ECS で Fluent Bit を使っている場合も同じように試せます。

検証環境

同じクラスターの中でも、Fluent Bit のバージョンは大きく離れていました。EC2 側は自分たちで入れたイメージを古いバージョンのまま使い続けていた一方で、Fargate 側はログルーターを AWS が管理しているので、新しいバージョンで動いていました。

ノイズとして片付ける前に

当初は CloudWatch Logs のサブスクリプションフィルターで、該当する文字列を通知対象から除外しようとしていました。

• 再送で復旧しており、ログの欠損は見当たらない
• ときどき発生するもので、実害はない

つまり「実害がないノイズ」と判断していたわけです。

https://dev.classmethod.jp/articles/tsnote-what-to-do-when-broken-connection-to-occurs-irregularly-in-fluent-bit/

上記の記事でも、このエラーは「想定された挙動」と紹介されており、対処としては Retry_Limit を増やす方法が挙げられています。

ところが、抑止のためのフィルターパターンを書きながら、違和感が出てきました。抑止してもエラーは出続けていて、見えなくなるだけです。

[error] レベルの本物のエラーを文字列で除外するのは、検知は正しいのに無視することになります。しかも Fluent Bit やプラグインのバージョンが変わってメッセージの形式が変われば、気付かないうちに効かなくなります。

調査 1: ログが増えたときに出ているわけではない

まず「送るログが多いときに出ているのでは」と考え、エラーの多かった Fargate 側について、送信先のロググループに届いたログ件数を 1 時間ごとに見てみました。

ログ件数は 10 日間を通してほぼ一定で、1 時間ごとのばらつきは 2% 程度でした。一方で broken connection は、1 件も出ない時間もあれば 8 件出る時間もあり、ログの量が変わらないなかで不規則に出ていました。

一時的に送信量が増えて失敗している、というわけではなさそうです。

調査 2: どこで発生しているのか

broken connection の行には送信先の名前しか出ないので、続けて出る Failed to send のエラーを出力プラグインごとに数えました。期間は調査 1 と同じ 10 日間です。

ログ量が最も多い出力に集中し、ログ量の少ない出力では 1 件も出ていません。

調査 1 のとおり、時間ごとの量の増減とは関係がありませんでした。それなのに出力ごとに見ると量の多いところだけで出ている。そこで、量そのものではなく、送信のたびに接続をどう使い回しているかに関係がありそうだ、と当たりをつけました。

調査 3: ほかに疑った 2 つの仮説

仮説 1: 接続の使用回数

Fluent Bit には net.keepalive_max_recycle（接続を何回使ったら破棄するか）という設定があります。「使いすぎた接続が壊れる」なら効くはずです。

同じエラーを扱った Fluent Bit の Issue（2022 年）でも値を小さくする方法が挙げられていたので、既定値の 2000 より小さい値にして broken connection の件数を比べました。

設定後の観察は 2 時間と短く、件数も少ないので、これだけで原因ではないとは言い切れません。ただ、このあと出てくる net.keepalive_idle_timeout のようなはっきりした差は出なかったので、ここでは深追いせず次に進みました。

仮説 2: バージョンが古いから

検証環境で触れたとおり、EC2 側の Fluent Bit は 2022 年リリースの v1.9.10 でした。当然「古いからでは」と疑いましたが、Fargate 側は v5.0.9 です。

件数を見ると、EC2 側は broken connection と Failed to send を合わせても 30 日で数件だったのに対し、Fargate 側は broken connection だけで 1 日 70 件前後出ていました。EC2 側と Fargate 側では送信量や送信先も違うので単純には比べられませんが、少なくとも「古いバージョンだから出ている」わけではなさそうです。

原因と考えられるもの: アイドル接続を閉じるタイミング

手がかりになったのは、AWS for Fluent Bit のリポジトリで公開されている、CloudWatch Logs 向けの推奨設定でした。2022 年に AWS for Fluent Bit チームが Issue として公開したもので、設定例の中に次のコメントがあります。

    # CW uses 6s idle timeout, FLB has 1.5s timer to check conns.
    # 4s ensures FLB always closes the conn itself, which we found
    # significantly reduces the rate of network error messages it outputs
    net.keepalive_idle_timeout 4s

CloudWatch Logs 側が 6 秒でアイドル接続を切り、Fluent Bit 側は 1.5 秒ごとに接続を点検している。だから 4 秒にすれば、必ず Fluent Bit のほうが先に接続を閉じる、という説明です。

この説明どおりなら、デフォルトの 30 秒のままでは、6 秒以上 30 秒未満アイドルだった接続を Fluent Bit が使い回したときに、サーバー側ではすでに切られていて送信が失敗することになります。

1.5 秒ごとの点検をソースコードで確かめる

Fluent Bit のソースコードでは、エンジンの起動時に 1500 ミリ秒ごとのタイマーを登録しています。

/* src/flb_engine.c */
ret = flb_sched_timer_cb_create(config->sched,
                                FLB_SCHED_TIMER_CB_PERM,
                                1500, cb_engine_sched_timer, config, NULL);

flb_sched_timer_cb_create() 自体は、指定したミリ秒ごとにコールバックを呼ぶタイマーを作るだけです。接続を点検しているのは、タイマーから呼ばれる cb_engine_sched_timer() の中の flb_upstream_conn_timeouts() です。

/* src/flb_engine.c */
static void cb_engine_sched_timer(struct flb_config *ctx, void *data)
{
    /* Upstream timeout handling */
    flb_upstream_conn_timeouts(&ctx->upstreams);
    ...
}

flb_upstream_conn_timeouts() は、使われずに待機している keepalive 接続を順に見て、待機時間が net.keepalive_idle_timeout（デフォルト 30 秒）以上になったものを閉じます。

/* src/flb_upstream.c */
now = time(NULL);
...
/* Check every available Keepalive connection */
mk_list_foreach_safe(u_head, tmp, &uq->av_queue) {
    u_conn = mk_list_entry(u_head, struct flb_connection, _head);

    if ((now - u_conn->ts_available) >= u->base.net.keepalive_idle_timeout) {
        prepare_destroy_conn(u_conn);
        ...
    }
}

EC2 側で使っている v1.9.10 でも、2026 年 9 月時点の master でも同じ実装です。ここから、接続が閉じられるタイミングについて 2 つのことがわかります。

• 点検は 1.5 秒ごとなので、待機時間が設定値に達してから最大 1.5 秒遅れて閉じる
• 待機時間は time(NULL) の秒単位で比べているので、実際の待機時間が設定値より 1 秒近く短くても、達したと判定されることがある

ローカルで確かめる

HTTP を受けるだけのサーバーに向けて Fluent Bit から 1 件だけ送り、その接続がいつ閉じられるかを見ました。

keepalive 接続の管理は出力プラグインに共通の仕組み（さきほどの flb_upstream_conn_timeouts()）なので、CloudWatch Logs の代わりに http 出力で確かめています。

受け側は Python の標準ライブラリだけで書いています。keep-alive を有効にするため、protocol_version を HTTP/1.1 にしています。

from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer

class Handler(BaseHTTPRequestHandler):
    protocol_version = "HTTP/1.1"  # keep-alive を有効にする

    def do_POST(self):
        self.rfile.read(int(self.headers["Content-Length"]))
        self.send_response(200)
        self.send_header("Content-Length", "0")
        self.end_headers()

    def log_message(self, *args):
        pass

ThreadingHTTPServer(("0.0.0.0", 8888), Handler).serve_forever()

Fluent Bit 側は dummy 入力で 1 件だけ作り、http 出力で送ります。接続の状態をログで見るため、Log_Level を debug にしています。

[SERVICE]
    Flush     1
    Log_Level debug

[INPUT]
    Name    dummy
    Samples 1

[OUTPUT]
    Name  http
    Match *
    Host  sink
    Port  8888
    Format json
    net.keepalive_idle_timeout 4s

net.keepalive_idle_timeout だけを 30s にした ka30.conf も用意し、Fluent Bit v5.1.2 のコンテナをそれぞれ 5 回ずつ起動しました。

docker network create katest
docker run -d --name sink --network katest \
  -v "$PWD/sink.py:/sink.py:ro" python:3-alpine python /sink.py

docker run -d --name ka4 --network katest \
  -v "$PWD/ka4.conf:/fluent-bit/etc/fluent-bit.conf:ro" fluent/fluent-bit:5.1.2 \
  /fluent-bit/bin/fluent-bit -c /fluent-bit/etc/fluent-bit.conf

docker logs ka4 2>&1 | grep -E 'is now available|keepalive idle timeout'

送信が終わって接続が待機状態になった行と、閉じられた行が出ます。

06:52:20.557  [debug] [upstream] KA connection #51 to sink:8888 is now available
06:52:24.048  [debug] [upstream] drop keepalive connection #-1 to sink:8888 (keepalive idle timeout)

この 2 行の時刻差を 5 回ずつ測った結果です。

4 秒の設定で 3.5 秒ほどで閉じているのは、さきほどの秒単位の比較によるものです。

なぜ 4 秒なのか

これを AWS の説明にある 6 秒と並べると、次のようになります。

設定値は秒単位なので、遅い側で見ると 4 + 1.5 = 5.5 < 6 となり、4 秒が「6 秒より前に閉じることを保証できる最大値」になります。5 秒だと 5 + 1.5 = 6.5 で保証が崩れます。

ただし、CloudWatch Logs 側が 6 秒で切るという点は自分では再現できませんでした。エンドポイントに接続して 35 秒までアイドルにしても切断されなかったので、ここでは「AWS の説明に沿って 4 秒にしたら、後述のとおり減った」という事実までにとどめます。

なぜサーバーが先に閉じると困るのか

これは Fluent Bit に限った話ではなく、HTTP/1.1 の仕様である RFC 9112 にも書かれている競合です。

A client, server, or proxy MAY close the transport connection at any time. For example, a client might have started to send a new request at the same time that the server has decided to close the "idle" connection.

サーバーがアイドル接続を閉じる瞬間と、クライアントが次のリクエストを送る瞬間が重なると、送信は失敗します。クライアント側で先に閉じておけば、少なくともサーバーのアイドルタイムアウトによる切断とは重ならなくなります。

結果

Fargate 側

エラーの件数が多い Fargate 側から先に、検証環境で net.keepalive_idle_timeout 4s を適用しました。Fargate 側のログルーター自身のログから、broken connection の行を日ごとに数えた結果です。

10 日前  約 70 件
9 日前   約 70 件
8 日前   約 60 件
7 日前   約 70 件
6 日前   約 60 件
5 日前   約 80 件
4 日前   約 80 件
3 日前   約 50 件
2 日前   約 60 件
1 日前   約 60 件
──────────── 適用
適用日   約 20 件（適用前後が混在）
1 日後   0 件
2 日後   0 件
3 日後   0 件
4 日後   0 件
5 日後   3 件
6 日後   2 件
7 日後   2 件
8 日後   4 件
9 日後   7 件
10 日後  6 件

適用日を除いて、前後 10 日間ずつを比べました。

broken connection は 96% 減り、CloudWatch Logs 向けに限れば 99% 減です。それに続いて出ていた送信失敗もほぼ消えました。

送信先のロググループに届いたログ件数は、適用前と適用後で 0.2% ほどしか違わないので、「その期間だけトラフィックが少なかった」わけではありません。

適用後 4 日間は 0 件でしたが、5 日目ごろから 1 日数件ずつ出ています。中身を分けると、次のとおりです。

• 適用後に残った約 20 件のうち、十数件は Firehose 向けです。適用前から 1 日 1〜2 件ほど出ていたもので、ほぼ同じ水準です。今回の設定は cloudwatch_logs の出力にだけ入れているので、対象外です
• broken connection ではありませんが、接続の初期化エラーは十数件から 30 件近くに増えています。接続を早めに閉じて張り直す回数が増えたぶん、張り直す側の失敗が増えたと考えられます

EC2 側

EC2 側にも、同じ 1 行を追加しました。

こちらは適用前の 30 日間で、broken connection と Failed to send を合わせても数件しか出ていませんでした。適用後の 10 日間では 0 件です。

もともとの件数が少ないので大きな差にはなりませんが、適用後は 1 件も出ておらず、Fargate 側と同じように効果はありそうです。

retry_limit も合わせて検討したい

cloudwatch_logs 出力の公式ドキュメントを読んでいて気付いたのですが、retry_limit はデフォルトが 1 です。そしてリトライの仕様には次のようにあります。

When a chunk exhausts all retry attempts or retries are disabled, the data is discarded by default.

つまり、1 回再送して失敗したら、そのログは捨てられます。

さきほどのローカル環境で、受け側が一時的に止まったときにどうなるかを試しました。

dummy 入力で 1 秒に 1 件ずつ送り、受け側のサーバーだけを 30 秒遅れて起動します。http 出力に Retry_Limit 5 を足したものと、足さないもの（デフォルトの 1）を比べました。再送は出力プラグインではなくエンジン側の仕組みなので、cloudwatch_logs 出力でも同じ仕組みで再送されます。

[OUTPUT]
    Name  http
    Match *
    Host  sink
    Port  8888
    Format json
    Retry_Limit 5

デフォルトでは、1 回目の再送までに受け側が戻っていなければ捨てられます。

08:31:18  failed to flush chunk '1-...946.flb', retry in 7 seconds
08:31:25  chunk '1-...946.flb' cannot be retried

retry_limit 5 では間隔を空けながら再送が続き、受け側が戻ったあとに届いています。

08:31:21  failed to flush chunk '1-...198.flb', retry in 8 seconds
08:31:29  failed to flush chunk '1-...198.flb', retry in 19 seconds
08:31:48  flush chunk '1-...198.flb' succeeded at retry 2

ただし、再送の回数を増やすだけなので、受け側が止まったままであれば、いずれは破棄されます。受け側を起動しないまま 3 分間動かした場合は、retry_limit 5 でも 21 件が破棄されました。

一時的な切断で失われるログを減らす設定、と考えるのがよさそうです。

retry_limit 5 は AWS の推奨設定にも含まれており、前半で紹介した記事でも挙げられていた対処です。

net.keepalive_idle_timeout でエラーの発生自体を減らし、retry_limit で残ったエラーによるログの破棄を防ぐ、という組み合わせになります。とくに broken connection が多く出ている環境では、合わせて導入を検討してみるとよいと思います。

導入する場合は、再送を待つあいだチャンクがメモリに残る時間が長くなるので、Fluent Bit のメモリ使用量も合わせて見ておくと安心です。

結論

追加したのは net.keepalive_idle_timeout 4s の 1 行でした。

[OUTPUT]
    Name cloudwatch_logs
    ...
    net.keepalive_idle_timeout 4s

検証環境の Fargate 側で、同程度のトラフィックで適用前後 10 日間ずつを比べると、broken connection は 約 670 件から約 20 件（96% 減） になりました。CloudWatch Logs 向けに限れば約 650 件から約 10 件（99% 減）で、残りの大半は設定の対象外の Firehose 向けです。

AWS の推奨設定にある retry_limit 5 も、一時的な送信失敗によるログの破棄を防ぐのに有効でした。エラーがまだ多く残る環境では、合わせて検討してみてください。

おわりに

最初は通知を止めて終わりにするつもりでした。でもそうしていたら、エラーは出続けたまま見えなくなっていたはずです。ちゃんと原因を調べてみてよかったです。

同じように broken connection が多発して悩んでいる方の参考になれば幸いです。