本記事はQiitaに投稿していたものを、Qiitaのコミュニティガイドライン追加に伴い削除の可能性を考慮してこちらに移行しました。理由は、fluentdからElasticsearchにログを投げ込み処理は弊社のOpenShiftのログ収集機能で利用しているものであり、記事投稿が自社で利用している技術の宣伝がないかといわれれば否定できないためです。

先にまとめ

以下のすべての条件を満す時、"Cannot get new connection from pool."というエラーが、fluentd起動後しばらく(自分のテストしたときは1日弱)してから発生し、以後すべてのログの送信ができなくなる

elasticsearchの_nodes APIの返すレスポンスにクラスタのノードのIPの情報が含まれていない環境。例）AWS elasticsearch
fluent-plugin-elasticsearchもしくはfluent-plugin-aws-elasticsearch-service のv1.9.0以下を使っている。 (1.9.1で修正済みです)
Dynamic configuration をつかっている

詳細

問題の概要

fluentdを使ってAWS elasticsearchにログを転送していると、最初は問題なくログを送信できているのにしばらくすると突然"Cannot get new connection from pool.“というエラーを出して、以降毎回送信のたびに同じエラーで送信が全くできない問題が発生しました。同じ様な現象はGitHubのissueやフォーラムなどでも議論されていました。

これらの議論を読むと、AWS elasticsearchはmanagedなサービスで _nodes API で通常返すはずのnodeのIP情報が含まれていないこと。そして、Elastic Search のRuby Clientは一定リクエストごとにnodeのIPを取得しなおしてコネクションの再生成をしたり、通信失敗時に同様の処理を行ったりすることが指摘されていました。それらの機能は、fluent-plugin-elasticsearchのプラグインのreload_connectionsやreload_on_failureをfalseに設定すれば無効化でき(後者はデフォルトがfalse)、実際にその設定により解決したという報告もありました。しかし、その設定をしても変化がないという報告もあり、私も同じ現象に悩んでいました。

問題の追及

エラー発生時のスタックトレースから、エラーが発生するときはget_connectionがnilを返しているはずで、それはコネクションのリロードがfalseに設定しているのに起きているはずではと考え色々デバッグしていました。

で、最終的に見つけた結論はRubyでは文字列の"false"はboolで評価されるとtrueになる、ということに起因する問題です。

irb(main):001:0> a = "false"
=> "false"
irb(main):002:0> "OUT" if a
=> "OUT"
irb(main):003:0> "OUT" if false
=> nil

Elasticsearch Ruby Clientでリロードするかどうかの部分はこういう判定になっています。

reload_connections!         if reload_connections && counter % reload_after == 0

https://github.com/elastic/elasticsearch-ruby/blob/v2.0.0/elasticsearch-transport/lib/elasticsearch/transport/transport/base.rb#L70

reload_connections というフィールドはこのように代入されており、FixNum であることが期待されています。

@reload_connections = options[:reload_connections]
@reload_after    = options[:reload_connections].is_a?(Fixnum) ? options[:reload_connections] : DEFAULT_RELOAD_AFTER

なのですが、Issueコメントによると無効化したければfalseを指定すればいいよと書いており、実際falseを渡せば完全に無効化される処理になります。

github.com

じゃあ、プラグイン側で設定ファイルにfalseと指定すれば動く気もして、実際プラグインでdynamic configurationを指定しなければ、期待通り動きます。これはreload_connectionsなどをboolとして渡しているからです。これが、ある人はこの設定を指定すれば動くようになったとコメントしている理由ではないかと考えています。 https://github.com/uken/fluent-plugin-elasticsearch/blob/v1.9.0/lib/fluent/plugin/out_elasticsearch.rb#L41-L42

ところがdynamic configuration を指定していると、設定パラメータはstring型になります。これは設定ファイルを式として評価するために一旦文字列として扱う必要があるから、が理由な気がします。 https://github.com/uken/fluent-plugin-elasticsearch/blob/v1.9.0/lib/fluent/plugin/out_elasticsearch_dynamic.rb#L15-L16

ちなみに設定ファイルに

reload_conncetoins "#{false}"

のように評価結果がfalseになる式を記述しても、評価結果が文字列になるものしかチェックしないせいか設定は無視され、デフォルトの文字列としての"true"や"false"が使われます。

いずれにしても、reload_conncetionsとreload_on_failureは文字列型以外の値をとることなくElasticsearch Clientに渡され、文字列としてifの条件判定に使われるため、falseと設定ファイルに指定してもtrueと評価され、どこかのタイミングでreload_connections!が実行され、その瞬間にnodeのIPがとれずにconnectionsが空になり、以降のログ送信が全て失敗する、という問題が発生する流れな気がしています。なお、AWS固有の機能を追加している、 fluent-plugin-aws-elasticsearch-service でも同じコードを通るので、dynamic configuration をつかっていると同じ問題が発生します。

https://github.com/uken/fluent-plugin-elasticsearch/blob/v1.9.0/lib/fluent/plugin/out_elasticsearch_dynamic.rb#L250-L253 https://github.com/uken/fluent-plugin-elasticsearch/blob/v1.9.0/lib/fluent/plugin/out_elasticsearch_dynamic.rb#L54-L55

コードを抜粋するとこんな感じです。Dynamic configurationの目的上、設定ファイルの値を文字列型として扱うのはしょうがないかなあという気がするので、クライアントに渡すところでboolに変換するのが解決策ではないでしょうか。

  config_param :reload_connections, :string, :default => "true"
  config_param :reload_on_failure, :string, :default => "false"
#<snip>

      transport = Elasticsearch::Transport::Transport::HTTP::Faraday.new(connection_options.merge(
                                                                          options: {
                                                                            reload_connections: @dynamic_config['reload_connections'],
                                                                            reload_on_failure: @dynamic_config['reload_on_failure'],
                                                                            resurrect_after: @dynamic_config['resurrect_after'].to_i,
                                                                            retry_on_failure: 5,
                                                                            transport_options: {
                                                                              request: { timeout: @dynamic_config['request_timeout'] },
                                                                              ssl: { verify: @dynamic_config['ssl_verify'], ca_file: @dynamic_config['ca_file'] }
                                                                            }
                                                                          }), &adapter_conf)

問題の解決と現状

というわけで、以下のPRを作成して、無事1.9.1としてマージしてもらいました。感謝！

github.com

fluent-plugin-elasticsearch | RubyGems.org | your community gem host

また、fluent-plugin-aws-elasticsearch-serviceでも同じ問題が起きる件に関しては、fluent-plugin-elasticsearchの最新版に依存するように指定しているのでパッケージしなおせば解決するはずですが作者からの反応がない状態です。あまりよくはないなあと思いつつ、hotfix版としてforkしたうえでruby gemsも作成しています。

github.com

fluent-plugin-aws-elasticsearch-service-hotfix | RubyGems.org | your community gem host