読者です 読者をやめる 読者になる 読者になる

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

ちなみにですが、Linux(CentOS)の場合でも同様の事象は起きました。

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ドライバも非常に賢いなぁと関心させられますね。