#Fluentd トラブル相談 3 - Windows版のtd-agent 4でメモリリークが発生する - 2022-10-03

第3回目、久しぶりのFluentdトラブル相談のご紹介です。今回は「Windows版のtd-agent v4で使用メモリが右肩上がりに上昇していく」という事例です。

memleak-graph

ご相談内容

具体的なご相談内容は以下のようなものでした。

Windows版のtd-agentでFluentdプロセスの使用メモリが右肩上がりに上昇していく
td-agent v4系に更新してから発生していて、td-agent v3系では発生していない
使用しているプラグインは以下で、10数個の<source>に対して個別に<filter>および<match>を割り当て
- in_tail
- in_windows_eventlog2
- fileter_recordmodifier
- out_forward
out_forwardではTLSを使用している

解説 - バグ調査の定石は被疑箇所の地道な絞り込み

Fluentdを使用していて、メモリリークと見られる現象、すなわちメモリ使用量が右肩上がりに増加していく問題に遭遇したという報告は、Fluentdプロジェクトのissueでもたびたび投稿されています。しかしFluentdは非常に柔軟な設定ができるため、その原因は千差万別です。メモリリークの原因がサードバーティープラグイン側にあったり、そもそもバッファが溜まり続けているだけで、メモリリークではないというケースも多いです。

デバッグツールでピンポイントに原因を特定できるケースもありますが、ツールを通すとプログラムの実行速度が極端に遅くなり、思うようにデバッグできないことも多いです。

そのような状況では、原因を特定するために被疑箇所を地道に絞り込んでいく必要があります。

どのように調査したのか

sigdumpによるメモリプロファイル取得

Fluentdは、sigdumpというライブラリにより、任意のタイミングでRubyのGC（Garbage Collection）の情報やアロケートされているオブジェクトの情報を取得することができますので、まずはこれを活用してメモリの使用状況を把握することを試みました。UNIX環境では、Fluentdプロセスに対してCONTシグナルを送信すると、/tmp/sigdump-<pid>.logに情報が出力されます。しかし、今回のお客様環境はWindowsです。お問い合わせ頂いた時点では、Windows環境において直接的にsigdumpをトリガーする方法は用意されていませんでした。

そこで、sigdumpによるプロファイルを簡単に収集できるようにするプラグインfluent-plugin-sigdumpを作成し、お客様に提供しました。

https://github.com/fluent-plugins-nursery/fluent-plugin-sigdump/

fluent.confに以下のような設定を追加すると、15分毎にsigdumpによるダンプを自動的に実行するようになります。

<source>
  @type sigdump
  path /path/to/dump
</source>

このプラグインでお客様側でデータを取得して頂き、内容を解析しましたが、頂いたデータからはメモリ使用量が増加していく傾向は見られませんでした。以下に解析したデータの一例を示します。

object-counts-graph

一方で、パフォーマンスモニターなどで取得したプロセス全体のメモリ使用量を確認すると、冒頭で示したように確かに右肩上がりにメモリ使用量が増加していく様子が見られます。このことは、メモリリークがRubyで記述されたスクリプトで発生しているのではなく、Cで書かれた部分（Ruby本体や、Cで書かれたRubyの拡張ライブラリや依存ライブラリ）で発生している可能性が高いことを示唆しています。

メモリープロファイラーの使用

メモリーリークの調査には、一般的にはメモリープロファイリングツールを使うのが効果的です。UNIX系ではValgrindというツールが有名です。Windowsの場合、弊社ではDr. Memoryというツールを使うことが多いです。

ただし、メモリープロファイラーを使用すると実行速度が極端に低下するなどといった副作用があり、検証したい構成そのままでメモリープロファイラーにかけると、遅すぎて検証できないということも多いです。実際にFluentdでも検証してみましたが、まともに動作しなかったため、直接メモリープロファイラーで調べる手法は断念せざるを得ませんでした。

設定変更による被疑箇所の絞り込み

以前のククログ記事「バグの直し方」でも紹介していますが、原因不明のバグは、プログラム構成を変更することによる被疑箇所の地道な絞り込みが、一見遠回りなように見えて近道なことが多いです。コツとしては、2分探索のように対象を大きく半分程度に分割していくことで、問題箇所を効率的に絞り込んでいくことができます。

プログラムコード自体の変更は大変ですので、まずは設定変更による被疑箇所の絞り込みを考えます。Fluentdの場合は大まかに以下のような流れでデータを処理します。

     Inputプラグイン ⇨ Filterプラグイン ⇨ Outputプラグイン

これをふまえ、以下のような流れで設定を変更していくことで、大まかに被疑箇所を絞り込むことができます。

Filterプラグインを省いてみる
- 省いたら再現しなくなる場合は、原因はFilterプラグインにある可能性が高い
- 省いても再現する場合は、原因はInputプラグインかOutputプラグインのどちらかにある可能性が高い
Outputプラグインを、何も行わないnullプラグインに変更してみる
- これで再現しない場合は、原因はOutputプラグインにある可能性が高い
Inputプラグインをdummyプラグイン等の単純なプラグインに変更してみる
- これで再現しない場合は、原因はInputプラグインにある可能性が高い
InputプラグインやOutputプラグインがそれぞれ複数ある場合は、それぞれ単一のプラグインのみを使用するようにしてみる
- 再現しないプラグインは被疑対象から外すことができる

ただしRubyのプログラムはGCによるメモリのバンプがあるため、短期的な実行では本当にそれがメモリーリークであるかどうかを判断することは難しい場合があります。それぞれのステップで、最低数時間程度の観測が必要です。

お客様の設定をこのような手順で絞り込んでいったところ、原因はout_forwardプラグインにあることがわかりました。さらにout_forwardの設定を一つ一つ絞り込んでいったところ、以下のことも分かりました。

TLSを使用している場合にのみ問題が再現する
tls_cert_logical_store_nameをtls_cert_pathに変更しても問題が再現する
- （tls_cert_logical_store_nameが依存するRubyのC拡張ライブラリであるcertstore_cの問題ではない）
tls_insecure_modeをfalseにすると問題が再現しない

プログラム変更による被疑箇所の絞り込み

上記に加え、実際には使われないコードパスも被疑対象から外していくと、Fluentdのコードとしては問題が以下の範囲にある、というところまで絞り込むことができました。

https://github.com/fluent/fluentd/blob/438a82aead488a86180cd484bbc4e7e344a9032b/lib/fluent/plugin_helper/socket.rb#L109-L159

       else
         cert_store = OpenSSL::X509::Store.new
... 
         begin
           if enable_system_cert_store
... 
             cert_store.set_default_paths
           end
... 
         end
... 
         context.set_params({})
         context.ciphers = ciphers
         context.verify_mode = OpenSSL::SSL::VERIFY_PEER
         context.cert_store = cert_store
         context.verify_hostname = verify_fqdn && fqdn
... 
       end
       Fluent::TLS.set_version_to_context(context, version, min_version, max_version)

以上のコードを見る限り、原因がFluentdに無いことはほぼ明らかで、依存しているライブラリの問題である疑いが強くなってきました。上記でもかなり被疑範囲は絞り込まれていますが、問題箇所をピンポイントで特定しておいた方が、ライブラリ側を調査するときに作業を進めやすくなります。とは言えこれ以上は設定変更だけで問題箇所を絞り込むことはできませんので、Fluentdのプログラム自体を変更して問題を絞り込んでいきました。

結果、Fluentdのコードレベルでは原因が以下の1行のみにあることが特定できました。

125               cert_store.set_default_paths

依存ライブラリの調査

cert_store.set_default_pathsというメソッドの実体はOpenSSLのX509_STORE_set_default_paths()であり、Rubyのopensslライブラリを通じて呼び出しています。このため、問題箇所は以下のいずれかにあるということになります。

Rubyのopensslライブラリ
OpenSSL本体

まずRubyのopensslライブラリについてコードを確認しましたが、メモリリークを発生させるようなコードには見えません。問題が発生していないtd-agent 3.8のRuby 2.4からコードがほぼ変わっていない点から考えても、ここに問題があるとは考えられません。

https://github.com/ruby/ruby/blob/c9c2245c0a25176072e02db9254f0e0c84c805cd/ext/openssl/ossl_x509store.c#L372-L383

static VALUE
ossl_x509store_set_default_paths(VALUE self)
{
   X509_STORE *store;

   GetX509Store(self, store);
   if (X509_STORE_set_default_paths(store) != 1){
       ossl_raise(eX509StoreError, NULL);
   }

   return Qnil;
}

そこで問題がOpenSSL本体にあると考え、以下のようなサンプルプログラムを作成し

#include <openssl/x509v3.h>
#include <stdio.h>

int
main(int argc, char *argv[])
{
  X509_STORE *store = X509_STORE_new();
  int result = X509_STORE_set_default_paths(store);
  X509_STORE_free(store);
  return 0;
}

前述のDr. Memoryで調査しました。FluentdをDr. Memoryで動作させるのは困難でしたが、この程度の小さなプログラムであれば問題なく動作させることができます。サンプルプログラムのビルド方法やDr. Memoryの使い方の詳細はGitHubのissueに記載しています。

結果は以下のようになりました。X509_STORE_set_default_paths()を呼び出すと820バイトのメモリリークが発生することが分かります。

Dr. Memory version 2.5.0 build 0 built on Oct 18 2021 03:01:22
Windows version: WinVer=105;Rel=2009;Build=19044;Edition=Professional
Dr. Memory results for pid 20624: "a.exe"
Application cmdline: "a.exe"
Recorded 124 suppression(s) from default C:\Program Files (x86)\Dr. Memory\bin64\suppress-default.txt

Error #1: LEAK 121 direct bytes 0x0000022a61f90600-0x0000022a61f90679 + 0 indirect bytes
# 0 replace_malloc                             [d:\a\drmemory\drmemory\common\alloc_replace.c:2580]
# 1 libcrypto-1_1-x64.dll!simplify_path
# 2 libcrypto-1_1-x64.dll!malloc_copy_string
# 3 libcrypto-1_1-x64.dll!get_relative_path
# 4 libcrypto-1_1-x64.dll!openssl_relocation
# 5 libcrypto-1_1-x64.dll!X509_get_default_cert_file
# 6 libcrypto-1_1-x64.dll!by_file_ctrl
# 7 libcrypto-1_1-x64.dll!X509_LOOKUP_ctrl
# 8 libcrypto-1_1-x64.dll!X509_STORE_set_default_paths
# 9 main

Error #2: LEAK 313 direct bytes 0x0000022a61f906a0-0x0000022a61f907d9 + 0 indirect bytes
# 0 replace_malloc                             [d:\a\drmemory\drmemory\common\alloc_replace.c:2580]
# 1 libcrypto-1_1-x64.dll!simplify_path
# 2 libcrypto-1_1-x64.dll!malloc_copy_string
# 3 libcrypto-1_1-x64.dll!openssl_relocation
# 4 libcrypto-1_1-x64.dll!X509_get_default_cert_file
# 5 libcrypto-1_1-x64.dll!by_file_ctrl
# 6 libcrypto-1_1-x64.dll!X509_LOOKUP_ctrl
# 7 libcrypto-1_1-x64.dll!X509_STORE_set_default_paths
# 8 main

Error #3: LEAK 97 direct bytes 0x0000022a61fbef20-0x0000022a61fbef81 + 0 indirect bytes
# 0 replace_malloc                                   [d:\a\drmemory\drmemory\common\alloc_replace.c:2580]
# 1 KERNEL32.dll!GetPhysicallyInstalledSystemMemory +0x22bf   (0x00007fff6bce3530 <KERNEL32.dll+0x3530>)
# 2 libcrypto-1_1-x64.dll!simplify_path
# 3 libcrypto-1_1-x64.dll!malloc_copy_string
# 4 libcrypto-1_1-x64.dll!get_relative_path
# 5 libcrypto-1_1-x64.dll!openssl_relocation
# 6 libcrypto-1_1-x64.dll!X509_get_default_cert_dir
# 7 libcrypto-1_1-x64.dll!dir_ctrl
# 8 libcrypto-1_1-x64.dll!X509_LOOKUP_ctrl
# 9 libcrypto-1_1-x64.dll!X509_STORE_set_default_paths
#10 main

Error #4: LEAK 289 direct bytes 0x0000022a61fbefb0-0x0000022a61fbf0d1 + 0 indirect bytes
# 0 replace_malloc                             [d:\a\drmemory\drmemory\common\alloc_replace.c:2580]
# 1 libcrypto-1_1-x64.dll!simplify_path
# 2 libcrypto-1_1-x64.dll!malloc_copy_string
# 3 libcrypto-1_1-x64.dll!openssl_relocation
# 4 libcrypto-1_1-x64.dll!X509_get_default_cert_dir
# 5 libcrypto-1_1-x64.dll!dir_ctrl
# 6 libcrypto-1_1-x64.dll!X509_LOOKUP_ctrl
# 7 libcrypto-1_1-x64.dll!X509_STORE_set_default_paths
# 8 main

===========================================================================
FINAL SUMMARY:

DUPLICATE ERROR COUNTS:

SUPPRESSIONS USED:

ERRORS FOUND:
　      0 unique,     0 total invalid heap argument(s)
      0 unique,     0 total warning(s)
      4 unique,     4 total,    820 byte(s) of leak(s)
      0 unique,     0 total,      0 byte(s) of possible leak(s)
ERRORS IGNORED:
      1 potential leak(s) (suspected false positives)
         (details: C:\Users\aho\AppData\Roaming\Dr. Memory\DrMemory-a.exe.20624.000\potential_errors.txt)
      7 unique,     7 total,    550 byte(s) of still-reachable allocation(s)
         (re-run with "-show_reachable" for details)

1回の呼び出しでのリーク量としてはさほど大きくありませんが、Fluentdの該当箇所は、TLS通信が発生するたびに呼び出されます。お客様環境ではout_forward用の<match>セクションでflush_interval 10およびheartbeat_interval 10が設定されていたため、毎分それぞれ6回、計12回の通信が発生します。また、同様の<match>セクションが一つではなく10数箇所あったため、トータルで毎分120回以上の通信が発生します。 1時間辺りで約6MB、1日で140MB以上のメモリリークが蓄積することになります。

OpenSSLのアップストリームのコードを確認したところ、メモリリークの原因となっているopenssl_relocation()やsimplify_path()という関数は呼ばれていませんし、そもそも存在していませんでした。

int X509_STORE_set_default_paths(X509_STORE *ctx)
{
   X509_LOOKUP *lookup;


   lookup = X509_STORE_add_lookup(ctx, X509_LOOKUP_file());
   if (lookup == NULL)
       return 0;
   X509_LOOKUP_load_file(lookup, NULL, X509_FILETYPE_DEFAULT);


   lookup = X509_STORE_add_lookup(ctx, X509_LOOKUP_hash_dir());
   if (lookup == NULL)
       return 0;
   X509_LOOKUP_add_dir(lookup, NULL, X509_FILETYPE_DEFAULT);


   /* clear any errors */
   ERR_clear_error();


   return 1;
}

このことから、問題はOpenSSLのアップストリームにあるのではなく、MINGWのパッケージで当てているパッチに問題があるということが分かりました。

どのように解決したのか

回避方法の案内

上記の通り、今回発見されたメモリリークはX509_STORE_set_default_paths()が繰り返し呼び出されることで蓄積し、問題が深刻化します。同関数が繰り返し呼び出されないようにすれば、問題を大幅に軽減できます。

Fluentdのout_forwardにはkeepaliveという設定があり、これをtrueにすることで既存のコネクションが使い回されるようになり、X509_STORE_set_default_paths()が繰り返し呼び出されることも無くなります。既存のバージョン使用時の回避策として、まずはこの設定を案内しました。

根本原因の修正

上記はあくまでも回避策に過ぎませんので、根本的な修正についても検討しました。一般的に、メモリリークの修正は原因箇所さえ分かってしまえば簡単な場合が多いです。

本件についても数行程度の変更で修正できることは確認していましたが、アップストリームで修正されることが望ましいので、まずはMSYS2のMINGW-packagesプロジェクトにこの問題を報告しました。

Memory leak in OpenSSL relocation patch

続いて修正のプルリクエストも投げるつもりでしたが、メンテナーの方が素早く対応してくれ、修正パッチが作成されました。

openssl: fix leak when calling relocation related functions multiple times

ただし、最初のパッチではまだ十分に修正されていなかったため、こちらから残りの問題を修正するパッチを投稿し、無事これも取り込まれる形でマージされました。

td-agentとしては、RubyInstallerに標準添付されているOpenSSLではなく、MSYS2で提供される最新のOpenSSLを利用する形に修正して新しいバージョンv4.3.1.1をリリースし、お客様に提供しました。

以上の修正で、無事メモリーリークの問題は解決しました。

memleak-fixed-graph

サポートのご依頼を受け付けてます！

クリアコードではFluentdのサポートサービスを提供しています。 Fluentdに関するトラブルを抱えて困っている等ありましたら、ぜひこちらのお問い合わせフォームからご連絡ください。

ククログ