FireLens（Fluentd）を使った大容量ログ配信時に起きた問題と調査の足跡 - Sansan Tech Blog

Sansan Tech Blog

Sansanのものづくりを支えるメンバーの技術やデザイン、プロダクトマネジメントの情報を発信

FireLens（Fluentd）を使った大容量ログ配信時に起きた問題と調査の足跡

AWS Ruby Rails インフラ

まえがき

こんにちは。技術本部 Sansan Engineering Unit Nayoseグループでエンジニアをしている滑川です。私たちのグループは主に名寄せサービスの開発や改善を行っています。「名寄せ」とは、別々のデータとして存在する「同じ会社や人物のデータ」をひとまとめにグルーピングすることを指します。

名寄せサービスは運用開始から7年以上が経過し、サービスの成長とともに名寄せロジックも複雑化してきました。そのため、なぜ名寄せされた（あるいはされなかった）のかといった原因特定に時間がかかることが課題でした。この課題を解決するため、名寄せロジックのログ（以下、名寄せログ）を収集し、より迅速な調査・改善を可能にするプロジェクトに取り組みました。

私はこのプロジェクトでインフラ構築を主に担当しました。本記事では、その過程で得られた知見をご紹介したいと思います。
また、今回は思うようにいかず問題解決を諦めた箇所があります。諦める意思決定をした根拠も含めてご紹介します。

名寄せログ収集プロジェクトのゴール

名寄せロジックの詳細をロギングするに当たり、「ロギングすべき項目」と「それぞれのログサイズ」の調査から着手しました。コードリーディングやメトリクスのチェックを行い試算した結果、ワーストケースにおいてロギングしたい総量が 1 ログあたり最大 2MB、流量は 1GB/s に達することが判明しました。（大半は数百バイトであり、振れ幅が大きいです。）
これらは同期的な API の中でもロギングするため、それも考慮しておく必要があります。

それを踏まえて、本プロジェクトのゴールは同期処理内で作られる最大 2MB、流量 1GB/s という膨大なログを配信できるアーキテクチャを構築することでした。また、「調査に必要なログは可能な限り残す」というポリシーで進めていたため、最初からログ量の制限をせずにすべてのログを取得することを目指していました。

しかし試行錯誤の末ログサイズが 2MB に達するケースは断念し、最終的に 300KB までに制限する形で実現しました。

なぜこのような決断に至ったのか、試行錯誤の調査過程や得られた知見とともに紹介ます。

名寄せログ配信アーキテクチャ

Before

図1: 名寄せログ収集の仕組みを入れる前のアーキテクチャ (参考: https://aws.amazon.com/jp/blogs/news/under-the-hood-firelens-for-amazon-ecs-tasks/)

After

図2: 名寄せログ収集の仕組みを入れたアーキテクチャ

赤色で示された部分が、今回新たに構築したアーキテクチャです。
既存の AWS FireLens（以下、FireLens）を使用したログ配信アーキテクチャに合わせる形で、名寄せログ収集の仕組みを構築しました。
構築過程で直面した問題に対する工夫を反映した結果このような形に落ち着きました。

今回は次の3点にフォーカスして、発生した問題と現在の構成に至った理由を詳しくご紹介していきます。

A. Fluentd 上の名寄せログ gzip 圧縮
B. TCP ソケットを利用した Fluentd への名寄せログ送信
C. TCP ソケットで Fluentd に送信する名寄せログサイズの 300KB 制限

A. Fluentd 上の名寄せログ gzip 圧縮

概要

今回は Fluentd の aws-fluent-plugin-kinesis プラグインを使用して AWS Data Firehose（以下、Firehose）にログを送信しています。このプラグインには Firehose に送信するログを圧縮する compression オプションが存在するため、これを有効にすることで Fluentd のレイヤーでログ圧縮が可能になります。

しかし、この compression オプションを有効にして Firehose にログを送ると、S3 に到達したログを伸張できない問題が発生しました。

原因は圧縮してバイナリになったログ間に未圧縮の改行コードが挿入されていたことによるものでした。
この章では、この問題が発生する理由と原因にたどり着くまでの調査過程について紹介します。

発生した問題

aws-fluent-plugin-kinesis プラグインのログ圧縮機能を利用した時に S3 に送信されたログが伸張できない、というのが主な事象でした。

具体的には以下の事象が確認されました。

  • gzip のログファイルを伸張しようとすると、「ignore trailing garbage data」というメッセージと共に伸張される
  • S3 に置かれた伸張後のファイルには複数件のログがあるはずだが、実際には 1 件のログしか確認できない

ログが伸張できなくなる原因

結論から述べると、Fluentd 上で gzip 圧縮されたバイナリ間に、未圧縮の改行コードが挿入されていたことで、ログの伸張が不可能になっていました。
具体的には以下の過程で伸張不可能な gzip ファイルが生成されていました。

1. Fluentd でログを圧縮する
2. Fluentd がログ末尾に改行コードを追加し、Firehose へログを送信する
3. Firehose から S3 へログを送信し、複数のログを結合してファイルを配置する

図3: 伸張不可能な gzip ファイルが生成されるまでの過程


圧縮されたログファイルの最初のログにはヘッダーとフッターが存在するため、正常な gzip フォーマットと判断されます。しかし、2つ目以降のログには \n が挿入されるため、おそらくヘッダーが破損していると判断されて伸張されません。その結果、ログファイルを伸張すると1件のログしか確認できない状態になっていました。

Fluentd で圧縮後に \n を追加しているコードはこちらです。実際にプラグインの gem が動く環境で以下の検証コードを動かすと、文字列を圧縮した後に改行コードが追加されていることが確認できます。

# リンク先コードをコピペし、文字列を gzip 圧縮可能にする
# https://github.com/awslabs/aws-fluent-plugin-kinesis/blob/master/lib/fluent/plugin/kinesis_helper/compression.rb

data_formatter = ->(tag, time, record) {
  p "#{Gzip.compress(record)}"
}

org_data_formatter = data_formatter
data_formatter = ->(tag, time, record) {
  org_data_formatter.call(tag, time, record).chomp + "not compressed string\n"
}

data_formatter.call(1,2,3)
# => "\x1F\x8B\b\x00v>\xE1f\x00\x033\x06\x00\x9B\x8E\xD2m\x01\x00\x00\x00not compressed string\n"

結論

この問題を防ぐには、compression オプションを有効にする際に、合わせて append_new_line オプションを無効にすることで対応できます。

余談

原因も解決方法も単純でしたが、壊れたバイナリを見て原因を突き止めるまでにはかなりの時間を要しました。というのも当初は、ログの欠損により伸張がうまくいかないことを疑っていました。
その結果、gzip の仕様とバイナリを照らし合わせて読み解いたり、プラグインのコードリーディングをしたり、Fluentd にパッチを当ててログレコードを出力させたり、Firehose 上で Lambda を挟んで 1 レコードずつ伸張を試みたりと、さまざまなアプローチから試行錯誤してようやく解決に至りました。

ECS Exec を使ったデバッグ

ECS 上で Fluentd の検証を進める際、ECS のリモートコマンド実行機能を活用してデバッグを行いました。この機能により、 ECS のシェルにリモートアクセスして Fluentd のソースコードに直接プリントデバッグを仕込むことや、fluent.conf の設定を編集することも可能になります。ただしセキュリティリスクも伴うため、本番環境ではアクセスを制限することをお勧めします。ECS Exec の設定方法はこちらのガイドをご覧ください。

Fluentd コンテナのシェルでソースコードや fluent.conf を変更した後は、fluent-ctl restart {pid}を実行して変更を反映できます（詳細はこちらのリファレンスを参照）。

この手法は今回のケースに限らず非常に便利なので、ぜひ試してみてください。

B. TCP ソケットを利用した Fluentd への名寄せログ送信

概要

FireLens を利用してアプリケーションから Fluentd へログを送信する方法には、「Unixドメインソケット」と「TCPソケット」の2つがあります。詳しく知りたい方はこちらの記事をご覧ください。

名寄せログ配信アーキテクチャの章の図にも示した通り、元々アプリケーションログ配信では Unix ドメインソケットを使用していたため、名寄せログも同じく Unix ドメインソケットの採用を検討していました。しかし、1 ログあたりのサイズが大きいことに起因する問題が発生したため、最終的に TCP ソケットでログを送信することにしました。

この章では、大容量ログを Unix ドメインソケットで Fluentd へ送信する際に発生した問題と、TCP ソケットを選択した理由について紹介します。

発生した問題

Unix ドメインソケットで大容量ログを並列で Fluentd に送った時、一部のログが破損する、という事象が起きました。
実際にどのようなことが起きたのか実験してみます。

環境

  • ECS
    • vcpu: 16
    • memory: 32 GB
    • Fargate: 1.4.0
  • Fluentd (FireLens) version: 1.15.2
  • Ruby version: 3.2.2
  • Rails version: 6.1.7.8

再現手順とサンプル

Rails コンテナと Fluentd コンテナが動く ECS タスクを起動します。次に Rails コンテナ内で以下のスクリプトを実行して、Fluentdにログを送信してみます。
なお、FireLens はアプリケーションの標準出力からログを収集し、Unix ドメインソケットを通じて Fluentd に転送する役割を担っています。

logger = ActiveSupport::Logger.new('/proc/1/fd/1') # docker の標準出力としてログ出力できるパスを指定

loop do
  Parallel.each([*'A'..'Z'], in_processes: 16) do |str|
    logger.info({message: str * 1024 * 1024 * 2}.to_json) # 2MiB
  end
end

得られたログを確認すると、以下のようなパターンのログが見つかりました。
いずれも JSON フォーマットが崩れていることがわかります。

# ログが途中で途切れる
'{\"message\":\"RRRRRRRR...RRR'

# 二つのログが混ざる
'{\"message\":\"RRRR...RRRR{\"message\":\"SSSSS...SSS'

# 複数のログの一部が混ざり合う
'WWWWWWW...WWWWWWWZZZZZZZ...ZZZZZZUUUUU...UUUUUYYYYYYYY...YYYYYYYY'

# 数文字で終わる
'DDDDDDDDDDDD'

調査結果

  • ログサイズが小さい場合は問題が発生しなかった
  • ログが混ざる場合、32,768文字ごとに発生していた
  • 一部のログはJSONフォーマットを維持しており、すべてのログで問題が発生しているわけではない
  • FireLens のパラメータlog-driver-buffer-limitを変えても効果がなかった
  • ログを標準出力とファイルの両方に出力したところ、ファイルではログの破損が確認されなかった
  • Fluentd の ログを読み込む箇所で読み込んだログを出力した結果、この時点で既にログが破損していることが確認された

結論

Unix ドメインソケットで Fluentd にログを送ることを断念し、TCP ソケットを使用することにしました。

その意思決定をした理由は主に以下の3点です。

  • Unix ドメインソケットでのログ破損問題を解決できなかったこと
  • Unix ドメインソケットを採用した場合、既存のアプリケーションログへの悪影響が否定できないこと
  • FireLens によりブラックボックス化されている部分が多く、現在の問題を解決しても新たな問題に直面する可能性が否定できないこと

ただし、検証結果から得られた仮説を基に、今後時間を見つけて解決に向けて試行錯誤を続けたいと考えています。

C. TCP ソケットで Fluentd に送信する名寄せログサイズの 300KB 制限

概要

前章で紹介した問題から、Fluentd にログを送る際に Unix ドメインソケットを利用すると、ログサイズが大きい場合にログ破損が起きるケースを紹介しました。そしてその結果 TCP ソケットを利用することにしました。
しかし、新たに TCP ソケットでもログサイズが大きいことにより、ログ送信の遅延が発生することがわかりました。

結果的にこの問題は解消できず、ログサイズが大きい状態では想定したトラフィックを処理しきれないと判断し、ログサイズを制限することにしました。
この章では、大容量ログを TCP ソケットで Fluentd へ送信する際に発生した問題と、ログサイズ制限に至った経緯について紹介します。

発生した問題

TCP ソケットを利用して大容量ログを並列で Fluentd に送信する際、ログ送信に遅延が起きる問題が発生しました。
さらに、Fluentd では incoming chunk is broken: host="127.0.0.1" msg=74 というエラーメッセージも確認されました。このエラーメッセージから Fluentd が受け取ったログが意図したフォーマットではないこともわかります。

この問題の挙動を具体的に確認するために実験をしてみます。

再現手順とサンプル

環境は Unix ドメインソケットの検証時と同様になります。以下のスクリプトを実行して、Fluentd にログを送信してみます（fluent-logger-ruby ライブラリを使用）。

logger = Fluent::Logger::FluentLogger.new(nil, host: 'localhost', port: 24224)

loop do
  Parallel.each([*'A'..'Z'], in_processes: 16) do |str|
    logger.post('test', {message: str * 1024 * 1024 * 2})
    puts "time: #{Time.current}, str: #{str}"
  end
end

スクリプトを実行した結果、以下のプリント結果が得られました。

time: 2024-09-12 08:21:23 UTC, str: L
time: 2024-09-12 08:21:23 UTC, str: D
time: 2024-09-12 08:21:23 UTC, str: B
time: 2024-09-12 08:21:23 UTC, str: A
time: 2024-09-12 08:21:24 UTC, str: M
time: 2024-09-12 08:21:24 UTC, str: S
time: 2024-09-12 08:22:57 UTC, str: F
time: 2024-09-12 08:23:57 UTC, str: P
time: 2024-09-12 08:23:57 UTC, str: K
time: 2024-09-12 08:23:57 UTC, str: G
time: 2024-09-12 08:24:26 UTC, str: Q
time: 2024-09-12 08:24:44 UTC, str: I
time: 2024-09-12 08:25:44 UTC, str: U
time: 2024-09-12 08:28:00 UTC, str: T
time: 2024-09-12 08:29:12 UTC, str: C
time: 2024-09-12 08:29:12 UTC, str: E
time: 2024-09-12 08:30:08 UTC, str: R
time: 2024-09-12 08:30:47 UTC, str: N
time: 2024-09-12 08:30:54 UTC, str: X
time: 2024-09-12 08:31:09 UTC, str: W
time: 2024-09-12 08:31:55 UTC, str: Z
time: 2024-09-12 08:31:55 UTC, str: H
time: 2024-09-12 08:32:33 UTC, str: V
time: 2024-09-12 08:32:33 UTC, str: Y
time: 2024-09-12 08:32:33 UTC, str: O
time: 2024-09-12 08:32:33 UTC, str: J

アルファベットを 26 種類すべて送るだけで 11 分もかかっていることがわかります。
また、Fluentd 上では incoming chunk is broken: host="127.0.0.1" msg=74 というエラーメッセージが大量に出ていました。

調査結果

  • 問題の発生頻度はログサイズに依存し、サイズが大きくなるほど発生確率が上昇した
  • ログの欠損や混在は観測されなかった
  • Fluentd 上で発生したエラーメッセージ 「incoming chunk is broken: host="127.0.0.1" msg=74」 の「msg=74」は ASCII コードを示していた
    • このエラーメッセージは Fluentd のこちらから出力されており、Fluentd がログを受信した時点で既に破損している可能性が高い
  • アプリケーション側では、fluent-logger のこの部分で write_stream の取得待ちが発生していた

結論

検証の結果、Fluentd へのログ送信に TCP ソケットを利用しても、ログサイズが大きい場合は送信遅延が発生することが判明しました。
この結果を受け、大容量ログの全文送信を断念し、ログサイズに制限を設ける判断をしました。

その後、ログサイズと出力間隔をパラメータとした負荷テストを実施し、現実的な出力間隔で安定したログ送信を実現できる閾値として、300KB のサイズ制限を設定しました。
また、Unix ドメインソケットと比較して、 TCP ソケットの方が問題が起きるまでのログサイズに余裕があったため、 TCP ソケットを採用するに至りました。

余談

ここまで来ると、Fluentd を経由せずにアプリケーションから直接 Firehose にログを送る方法も検討の余地がありそうです。今回は以下の理由から見送りましたが、状況によっては Fluentd を通さないアプローチも有効かもしれません。

  • 同期処理内でロギングするため、Firehose のクォータ（ 1MiB/record の上限）により 2MB のログを送る時にアプリケーション側で圧縮が必要となり、レイテンシー悪化が懸念される
  • ECS コンテナ外部のサービスとの通信が発生するため、レイテンシーへの影響や可用性のリスクが避けられない

あとがき

本記事では、FireLens (Fluentd) を利用した大容量ログの収集と配信アーキテクチャ構築時に直面した問題、その解決策、ワークアラウンド、そしてそれらの意思決定について紹介しました。Fluentd へのログ送信時に Unix ドメインソケットを利用するとログが破損する問題や、TCP ソケットを利用すると送信が遅延する問題など、さまざまな障害に遭遇し、最終的にはログサイズを 300KB に制限することで安定したログ送信を実現できました。

このプロジェクトを通じて、複数のインフラレイヤーに跨ってデータを送受信するシステムの構築の難しさを身をもって体感しました。問題発生時、原因究明の前段の「どこで、何が、どうなったのか」という基本情報の収集さえ困難でした。これらを把握するため、各レイヤーにデバッグメッセージを仕込み、ソースコードを精読し、実験を繰り返し行いました。泥臭く一歩ずつ状況を把握し、可能性を潰していく作業でしたが、個人的にはとても楽しい時間でした。
また、困難に直面した際にチームメンバーからサポートを得やすい環境づくりの重要性も実感しました。日々の作業内容のまとめと共有を継続的に行ったことで、他のメンバーから有益なコメントを得られました。この行動がなければ問題の属人化が進み、厳しい状況でも助けを求めにくい状態に陥っていたと思います。属人性の排除につながるこうしたアクションは今後も続けていきたいです。

最後に、現在名寄せログの収集はプロダクション環境でリリースされ安定稼働していますが、前述の通り改善の余地は残されています。今回は「小さくても動くもの」をリリースする判断をしましたが、ワークアラウンドとした問題の調査は継続して行っていく予定です。

ここまでお読みいただき、ありがとうございました。

私たちNayoseグループが所属するデータ戦略部門では、Web開発エンジニア、アルゴリズムエンジニア、データエンジニアを募集しています。
少しでもご興味を持っていただけましたら、ぜひ面談だけでもお越しいただければ幸いです。

open.talentio.com
open.talentio.com
open.talentio.com

© Sansan, Inc.