Replica Setとfluent-plugin-mongoでハマった話
久しぶりのブログになってしまいました。リハビリも兼ねて、手短なネタでも書こうと思います。
Advent Calendarではないですが、FluentdとmongoDBの話です（ちょどブログをサボっていた時期はNode × mongoDB × Fluentdを組み合わせたアプリケーションの開発なんかをやってました）。
mongoDBのReplica SetとFluentdのfluent-plugin-mongoを使って、エージェントからのログをmongoDBに流す、といった王道（？）の処理をやろうとしたのですが、Replica Set非使用時はうまくいったのに、Replica Setにした途端にtd-agentがエラーを吐いて落ちるようになってしまったので、その原因と対処についてまとめます。
エラーの内容
2013-12-18 23:56:27 +0900 [error]: unexpected error error_class=Mongo::ConnectionFailure error=#<Mongo::ConnectionFailure: Failed to connect to any given member.> 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/mongo-1.8.6/lib/mongo/util/pool_manager.rb:182:in `connect_to_members' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/mongo-1.8.6/lib/mongo/util/pool_manager.rb:52:in `block in connect' 2013-12-18 23:56:27 +0900 [error]: <internal:prelude>:10:in `synchronize' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/mongo-1.8.6/lib/mongo/util/pool_manager.rb:47:in `connect' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/mongo-1.8.6/lib/mongo/mongo_replica_set_client.rb:181:in `block in connect' 2013-12-18 23:56:27 +0900 [error]: <internal:prelude>:10:in `synchronize' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/mongo-1.8.6/lib/mongo/mongo_replica_set_client.rb:170:in `connect' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/mongo-1.8.6/lib/mongo/mongo_client.rb:645:in `setup' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/mongo-1.8.6/lib/mongo/mongo_replica_set_client.rb:474:in `setup' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/mongo-1.8.6/lib/mongo/mongo_replica_set_client.rb:147:in `initialize' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluent-plugin-mongo-0.7.1/lib/fluent/plugin/out_mongo_replset.rb:51:in `new' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluent-plugin-mongo-0.7.1/lib/fluent/plugin/out_mongo_replset.rb:51:in `get_connection' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluent-plugin-mongo-0.7.1/lib/fluent/plugin/out_mongo.rb:169:in `get_or_create_collection' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluent-plugin-mongo-0.7.1/lib/fluent/plugin/out_mongo.rb:75:in `start' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/lib/fluent/plugin/out_copy.rb:50:in `block in start' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/lib/fluent/plugin/out_copy.rb:49:in `each' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/lib/fluent/plugin/out_copy.rb:49:in `start' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/lib/fluent/match.rb:40:in `start' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/lib/fluent/engine.rb:246:in `block in start' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/lib/fluent/engine.rb:245:in `each' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/lib/fluent/engine.rb:245:in `start' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/lib/fluent/engine.rb:204:in `run' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/lib/fluent/supervisor.rb:386:in `run_engine' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/lib/fluent/supervisor.rb:94:in `block in start' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/lib/fluent/supervisor.rb:198:in `call' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/lib/fluent/supervisor.rb:198:in `main_process' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/lib/fluent/supervisor.rb:173:in `block in supervise' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/lib/fluent/supervisor.rb:172:in `fork' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/lib/fluent/supervisor.rb:172:in `supervise' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/lib/fluent/supervisor.rb:87:in `start' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/lib/fluent/command/fluentd.rb:146:in `<top (required)>' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/1.9.1/rubygems/custom_require.rb:55:in `require' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/1.9.1/rubygems/custom_require.rb:55:in `require' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.41/bin/fluentd:6:in `<top (required)>' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/bin/fluentd:23:in `load' 2013-12-18 23:56:27 +0900 [error]: /usr/lib/fluent/ruby/bin/fluentd:23:in `<top (required)>' 2013-12-18 23:56:27 +0900 [error]: /usr/sbin/td-agent:7:in `load' 2013-12-18 23:56:27 +0900 [error]: /usr/sbin/td-agent:7:in `<main>' 2013-12-18 23:56:27 +0900 [info]: shutting down fluentd 2013-12-18 23:56:27 +0900 [info]: process finished code=0 2013-12-18 23:56:27 +0900 [warn]: process died within 1 second. exit.
環境
Fluentd(td-agent)@x.x.x.1 ---> mongoDB@x.x.x.2:27017,x.x.x.2:27018,x.x.x.2:27019
mongoDB
localhostに3台起動します（結論からするとここが落とし穴だったりするのですが）
OSはWindowsです。起動は以下のコマンド（プライマリの場合）。
> bin\mongod.exe --dbpath .\data --logpath .\logs\mongodb.log --port 27017 --replSet rs0 --rest
Fluentd(td-agent)
別マシン(x.x.x.1)で起動します。x.x.x.1からmongoDBへは、x.x.x.2でアクセス。
td-agent.confは、以下の設定（sourceは実際は別のものですが、サンプルとしてin_execを使っています）
<match test>
type copy
<store>
type stdout
</store>
<store>
type mongo_replset
nodes x.x.x.2:27017,x.x.x.2:27018,x.x.x.2:27019
database test
collection test
flush_interval 10s
</store>
</match>
<source>
type exec
tag test
command /tmp/test.sh
run_interval 10s
keys time,foo,bar,baz
time_format %Y-%m-%d %H:%M:%S
</source>ちなみに、実行するスクリプトは以下の様な形（in_execのデフォルトフォーマットがtsvなので、それに合わせてます）。
#!/bin/sh date=`date +"%Y-%m-%d %H:%M:%S"` echo -e "$date\\taaa\\tbbb\\tccc"
Replica Setを構築する
bin\mongo.exeを実行してReplica Setを構築します。
> config = { _id: "rs0", members: [ {_id: 0, host: "localhost:27017"}, {_id: 1, host: "localhost:27018"}, {_id: 2, host: "localhost:27019"} ] }
{
"_id" : "rs0",
"members" : [
{
"_id" : 0,
"host" : "localhost:27017"
},
{
"_id" : 1,
"host" : "localhost:27018"
},
{
"_id" : 2,
"host" : "localhost:27019"
}
]
}
> rs.initiate(config)
{
"info" : "Config now saved locally. Should come online in about a minute.",
"ok" : 1
}確認。
> rs.status()
{
"set" : "rs0",
"date" : ISODate("2013-12-18T14:20:44Z"),
"myState" : 1,
"members" : [
{
"_id" : 0,
"name" : "localhost:27017",
"health" : 1,
"state" : 1,
"stateStr" : "PRIMARY",
"uptime" : 263,
"optime" : Timestamp(1387376359, 1),
"optimeDate" : ISODate("2013-12-18T14:19:19Z"),
"self" : true
},
{
"_id" : 1,
"name" : "localhost:27018",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 82,
"optime" : Timestamp(1387376359, 1),
"optimeDate" : ISODate("2013-12-18T14:19:19Z"),
"lastHeartbeat" : ISODate("2013-12-18T14:20:44Z"),
"lastHeartbeatRecv" : ISODate("2013-12-18T14:20:44Z"),
"pingMs" : 0,
"syncingTo" : "localhost:27017"
},
{
"_id" : 2,
"name" : "localhost:27019",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 80,
"optime" : Timestamp(1387376359, 1),
"optimeDate" : ISODate("2013-12-18T14:19:19Z"),
"lastHeartbeat" : ISODate("2013-12-18T14:20:44Z"),
"lastHeartbeatRecv" : ISODate("2013-12-18T14:20:42Z"),
"pingMs" : 0,
"syncingTo" : "localhost:27017"
}
],
"ok" : 1
}どうやらうまくいったみたいですね。
td-agentを実行
今回はサービスからではなく直接td-agentを実行します。
# td-agent
そうすると、冒頭のエラーが発生しました。
原因と解決法
ググっても当たりが見つからず（最初はF/Wとかを疑ったり）、最終的にエラーの元になっているpool_manager.rbのコードを追うことで対処しました。
どうやら、td-agentがlocalhost:27017（＝Replica Setの各メンバーのname）に接続しようとして、エラーになっているみたいでした。エージェント(x.x.x.2)から見たら、localhost:27017にはmongoDBが存在しないので、エラーになるのは当然ですが、nodesパラメータに列挙したホストに接続しようとしてはくれないんですね。バグなのか、そういうものなのかは、判断がつかないのですが、王道の構成だと思うし、どこか見落としがあるんだろうなという気がしています…。
とりあえず、Replica Setを再構築し、各メンバーのnameがそれぞれ x.x.x.2:27017, x.x.x.2:27018, x.x.x.2:27019 になるように設定して試すと、うまく接続でき、ログも登録できました。再構築した時のconfigは以下の通りです。
> config = { _id: "rs0", members: [ {_id: 0, host: "x.x.x.2:27017"}, {_id: 1, host: "x.x.x.2:27018"}, {_id: 2, host: "x.x.x.2:27019"} ] }
（出力略）
> rs.initiate(config)なおここでも注意点として、rs.reconfig(config) でReplica Setの設定を更新できるはずなのですが、今回のようにnameをlocalhostから別アドレス（x.x.x.2）に変更しようとした場合は、以下のエラーになり、できません。
hosts cannot switch between localhost and hostname
そのため、最初からReplica Setを作りなおして対処しました（データディレクトリは再利用しましたが）。
まとめ
実際にReplica Setを組むような場合、それぞれ別サーバにDBを立てると思うので、今回のように同一マシンに3つDBを立てることはしないはずであり、検証環境であることが仇となった形、ですかね…。
ともあれ、無事に登録ができることが確認し、自動フェールオーバなども確認できました。できあがってみると、自動フェールオーバのあたり、Node(Mongoose)も、RubyのmongoDBドライバも非常に賢いなぁと関心させられますね。
