Syntax Error.

[Sy] fluentdとMongoDBを連携してたらfluentdが起動しなくなった（Capped Collection使用時）

2015/05/27

Node.js + fluentd + MongoDB という構成でログをfluentd経由でMongoDBに入れていたんですが、元々動いていた処理をしばらく放置してたらサーバーを再起動したタイミングでfluentdが起動しなくなってしまいました。

Node.jsのアプリが落ちたのでfluentdのログを見てみる

最初、Node.jsアプリのログをfluentd-loggerでfluentdに送るところで落ちて、原因がよくわかりませんでした。

そこでfluentdのログ（/etc/td-agent/td-agent.log）を見てみると、Rubyのエラーが起きて起動に失敗していることがわかりました。

・
・
・
2015-05-27 02:09:02 +0900 [error]: unexpected error error_class=Fluent::ConfigError error=#<Fluent::ConfigError: New configuration is different from existing collection: new = capped, old = normal>
・
・
・
2015-05-27 02:09:02 +0900 [info]: shutting down fluentd
2015-05-27 02:09:02 +0900 [info]: process finished code=0
2015-05-27 02:09:02 +0900 [warn]: process died within 1 second. exit.

確かに、プロセスを見ても起動してなかった・・・

$ ps ax | grep td-agent
3760 pts/1    S+     0:00 grep td-agent

エラーメッセージについて調べてみる

何かしらconfigについて怒られてるっぽいので調べてみると、どうやらログの流し込み先に指定している MongoDBのCollectionがCapped CollectionじゃないのにfluentdのconfigではCappedってなってることが問題 の様子。

・・・あ、確かに一度fluentd経由でCollection作られたあと、一度削除して手動で作っちゃってたかも。

ちなみにtd-agent.confの該当の記述はこう。

<match access.log>
  type mongo
  host localhost
  port 27017
  database mytest
  collection access_logs

  capped
  capped_size 256m

  flush_interval 10s
  include_time_key true
</match>

ということで今度はMongoDBのCollectionのステータスを確認。

$ mongo
MongoDB shell version: 2.6.6
connecting to: test
> use mytest
switched to db mytest
> db.access_logs.stats()
{
  "ns" : "mytest.access_logs",
  "count" : 4,
  "size" : 1216,
  "avgObjSize" : 304,
  "storageSize" : 8192,
  "numExtents" : 1,
  "nindexes" : 1,
  "lastExtentSize" : 8192,
  "paddingFactor" : 1,
  "systemFlags" : 1,
  "userFlags" : 1,
  "totalIndexSize" : 8176,
  "indexSizes" : {
    "_id_" : 8176
  },
  "ok" : 1
}

ここで、Capped Collectionだと本来は"capped" : trueというステータスがあるはずなのにない・・・。

やっぱり原因はCollectionを勝手に作りなおしちゃったことのような気がするので、一旦削除してfluentd経由で改めてCollectionを作ってもらう。

> db.access_logs.drop()

で、fluentdを起動しなおしてログをウォッチ。

$ sudo /etc/init.d/td-agent start
Starting td-agent:                                         [  OK  ]

起動成功。でも安心できない。さっきもここまでは一緒。（裏でコケてた）

/etc/td-agent/td-agent.logを確認。

・
・
・
2015-05-27 02:39:02 +0900 [info]: listening fluent socket on 0.0.0.0:24224
2015-05-27 02:39:02 +0900 [info]: listening dRuby uri="druby://127.0.0.1:24230" object="Engine"

おぉ、さっきエラーになってたところでlistening fluent socketってなってる！

プロセスも確認。

$ ps ax | grep td-agent
3788 ?        Sl     0:00 /usr/lib64/fluent/ruby/bin/ruby /usr/sbin/td-agent --group td-agent --log /var/log/td-agent/td-agent.log --daemon /var/run/td-agent/td-agent.pid
3791 ?        Sl     0:00 /usr/lib64/fluent/ruby/bin/ruby /usr/sbin/td-agent --group td-agent --log /var/log/td-agent/td-agent.log --daemon /var/run/td-agent/td-agent.pid
3809 pts/1    S+     0:00 grep td-agent

よしよし。起動してます。

MongoDBのCollectionのリストを見てみると、さっき削除したのに新たに作られてます。へーこのタイミングで先にCollectionだけ作ってるのか。

> show collections
access_logs
・
・

ステータスを見てみると、

> db.access_logs.stats()
{
    "ns" : "mytest.access_logs",
    "count" : 0,
    "size" : 0,
    "storageSize" : 268435456,
    "numExtents" : 1,
    "nindexes" : 1,
    "lastExtentSize" : 268435456,
    "paddingFactor" : 1,
    "systemFlags" : 1,
    "userFlags" : 0,
    "totalIndexSize" : 8176,
    "indexSizes" : {
        "_id_" : 8176
    },
    "capped" : true,
    "max" : NumberLong("9223372036854775807"),
    "ok" : 1
}

さっきはなかった"capped" : trueがある。予想通り。

気を取り直してNode.jsのアプリで落ちないか確認

では無事にfluentdが立ち上がったので、アプリからのログの流し込みがうまくいくか確認します。

・・・落ちませんでした！

Good ! Bad ...
Syntax Error.