Jubatus Proxy起動時エラー

[yesmi...@gmail.com]

はじめまして三田と申します。

以下の質問をさせて頂きます。

Jubatusを分散モードで利用しております。
今年の5月から問題なく稼働していましたが、
先週末から複数あるうちの１つのクライアント環境のプログラムからのJubatusへのリクエストでタイムアウトが発生するようになり、
調べたところ、Jubatus Proxyが落ちていました。

再度、Jubatus Proxyを起動させようとしましたが、
（以前は問題なく起動できていたのが）
以下のエラーが出て起動できなくなりました。

ERROR [zk.cpp:171] failed to create ZooKeeper ephemeral node: /jubatus/jubaproxies/recommender/172.31.7.244_9199: no node (-101)
FATAL [proxy.cpp:101] exception when starting RPC server: Dynamic exception type: jubatus::core::common::exception::runtime_error::what: Failed to register_proxy

お忙しい中申し訳ございませんが、こちらのエラーの原因をご教授頂ければと思います。

なお他のクライアント環境ではJubatus Proxyは動き続け問題なくリクエストできている状態です。

バージョンは以下になります。
jubarecommender_proxy -v
jubatus-0.9.0 (jubarecommender_proxy)

以下起動時エラーメッセージ全文

sudo jubarecommender_proxy --zookeeper 172.31.7.71:2181,172.31.13.55:2181,172.31.20.188:2181
2016-09-27 19:25:49,914 9229 INFO  [server_util.cpp:514] starting jubarecommender_proxy 0.9.0 RPC server at 172.31.7.244:9199
    pid                  : 9229
    user                 : root
    timeout              : 10
    zookeeper timeout    : 10
    interconnect timeout : 10
    thread               : 4
    logdir               :
    log config           :
    zookeeper            : 172.31.7.71:2181,172.31.13.55:2181,172.31.20.188:2181

2016-09-27 19:25:49,914:9229(0x7fb7a1dea7c0):ZOO_INFO@log_env@726: Client environment:zookeeper.version=zookeeper C client 3.4.8
2016-09-27 19:25:49,914:9229(0x7fb7a1dea7c0):ZOO_INFO@log_env@730: Client environment:host.name=ip-172-31-7-244.ap-northeast-1.compute.internal
2016-09-27 19:25:49,914:9229(0x7fb7a1dea7c0):ZOO_INFO@log_env@737: Client environment:os.name=Linux
2016-09-27 19:25:49,914:9229(0x7fb7a1dea7c0):ZOO_INFO@log_env@738: Client environment:os.arch=3.10.0-327.18.2.el7.x86_64
2016-09-27 19:25:49,914:9229(0x7fb7a1dea7c0):ZOO_INFO@log_env@739: Client environment:os.version=#1 SMP Thu May 12 11:03:55 UTC 2016
2016-09-27 19:25:49,914:9229(0x7fb7a1dea7c0):ZOO_INFO@log_env@747: Client environment:user.name=centos
2016-09-27 19:25:49,914:9229(0x7fb7a1dea7c0):ZOO_INFO@log_env@755: Client environment:user.home=/root
2016-09-27 19:25:49,914:9229(0x7fb7a1dea7c0):ZOO_INFO@log_env@767: Client environment:user.dir=/home/centos
2016-09-27 19:25:49,914:9229(0x7fb7a1dea7c0):ZOO_INFO@zookeeper_init@800: Initiating client connection, host=172.31.7.71:2181,172.31.13.55:2181,172.31.20.188:2181 sessionTimeout=10000 watcher=0x7fb7a12d21c0 sessionId=0 sessionPasswd=<null> context=0x184b740 flags=0
2016-09-27 19:25:49,917:9229(0x7fb79a46c700):ZOO_INFO@check_events@1728: initiated connection to server [172.31.20.188:2181]
2016-09-27 19:25:49,924:9229(0x7fb79a46c700):ZOO_INFO@check_events@1775: session establishment complete on server [172.31.20.188:2181], sessionId=0x3575620e5970001, negotiated timeout=10000
2016-09-27 19:25:49,924 9232 INFO  [zk.cpp:644] got ZooKeeper event: type SESSION_EVENT(-1), state CONNECTED_STATE(3)
2016-09-27 19:25:49,924 9232 INFO  [zk.cpp:655] ZooKeeper session established: connected to 172.31.20.188:2181, negotiated timeout 10000 ms
2016-09-27 19:25:50,954 9229 INFO  [proxy.cpp:83] start listening at port 9199
2016-09-27 19:25:50,975 9229 ERROR [zk.cpp:171] failed to create ZooKeeper ephemeral node: /jubatus/jubaproxies/recommender/172.31.7.244_9199: no node (-101)
2016-09-27 19:25:50,975 9229 FATAL [proxy.cpp:101] exception when starting RPC server: Dynamic exception type: jubatus::core::common::exception::runtime_error::what: Failed to register_proxy
    #0 [jubatus::core::common::exception::error_api_func_*] = lock_service::create
    #0 [jubatus::core::common::exception::error_at_file_*] = ../jubatus/server/common/membership.cpp
    #0 [jubatus::core::common::exception::error_at_line_*] = 231
    #0 [jubatus::core::common::exception::error_at_func_*] = void jubatus::server::common::register_proxy(jubatus::server::common::lock_service&, const string&, const string&, int)

よろしくお願いいたします。

[Ryohei IMAMASU]

三田様

Jubatus Team の 今増 です。

ご報告、ご質問 ありがとうございます。

ご提示いただいたログから、ZooKeeper 上にノードを作る際にエラーとなっていることが想定されます。

お手数ですが、以下を教えていただけますでしょうか。

1. ZooKeeper のバージョン

2. ご報告いただいたエラーが発生した際の ZooKeeper のログ

3. ZooKeeper の設定ファイル

また、JubaProxy が落ちていた というのも気になる点です。

JubaProxy が落ちた際のログもありましたら教えていただけますでしょうか?

よろしくお願いいたします。

[yesmi...@gmail.com]

Jubatus Team  今増 さま

お忙しい中、ご確認ありがとうございます。

三田です。

＞1. ZooKeeper のバージョン

 3.4.8になります。

＞2. ご報告いただいたエラーが発生した際の ZooKeeper のログ

3台構成で2台についてコンソールログが出力されていましたので

（メッセージは微妙に違いますので）それぞれ添付いたします。

 ＞3. ZooKeeper の設定ファイル

添付いたします。

 

＞また、JubaProxy が落ちていた というのも気になる点です。

＞JubaProxy が落ちた際のログもありましたら教えていただけますでしょうか?

3台構成で3台ともコンソールログが出力されていましたので

（メッセージは微妙に違いますので）それぞれ添付いたします。

お手数をお掛けいたしますがよろしくお願いいたします。

 

[yesmi...@gmail.com]

Jubatus Team  今増 さま

添付ファイルのファイル名がばけてしまったので

再度アップしなおします。

よろしくお願いいたします。

[yesmi...@gmail.com]

 Jubatus Team  今増 さま

度々すみません。

やはりファイル名が化けてしまいますので、

添付ファイルについての補足説明をいたします。

それぞれのログファイルの中身に時間が記載されていますが、

2016-09-23 17時台のログがjubatusプロキシがダウンしたであろう時の

zookeeperのコンソールログ（3台それぞれファイルを分けて3ファイル）です。

2016-09-27 19時台のログがjubatusプロキシ起動時エラーになった時の

zookeeperのコンソールログ（2台それぞれファイルを分けて2ファイル）です。

お手数をお掛けいたしますがよろしくお願いいたします。

[Ryohei IMAMASU]

三田様

Jubatus Team 今増 です。ログの提供ありがとうございます。

ログを確認させていただいたところ、ZooKeeper 3号機のデータが消えているように見えました。

---

2016-09-23 17:03:56,788 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:QuorumPeer@533] - currentEpoch not found! Creating with a reasonable default of 1. This should only happen when you are upgrading your installation

2016-09-23 17:03:56,791 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:QuorumPeer@548] - acceptedEpoch not found! Creating with a reasonable default of 1. This should only happen when you are upgrading your installation

  
…


2016-09-23 17:19:39,031 [myid:3] - WARN  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Learner@377] - Got zxid 0x100008483 expected 0x1

---

おそらくなのですが、CentOS の tmpwatch によって、ZooKeeper のトランザクションログが削除され、ZooKeeper 上のデータがおかしくなっているのではないかと想像されます。

ZooKeeper の dataDir を /tmp/zookeeper
 ではなく、別のところ（例えば、/var/zookeeper ) のように設定して運用していただいたほうが良いかと思います。

よろしくお願いいたします。

[yesmi...@gmail.com]

Jubatus Team 今増さま

お手数をおかけしております。三田です。

お忙しい中、ご確認ありがとうございます。

 /tmp/zookeeper/version-2ディレクトリの中を1号機と3号機で比べてみると、

1号機

-rw-r--r--. 1 root root 67108880  9月 27 21:26 log.100000001

3号機

-rw-r--r--. 1 root root        1  9月 23 17:03 acceptedEpoch
-rw-r--r--. 1 root root        1  9月 23 17:19 currentEpoch
-rw-r--r--. 1 root root 67108880  9月 27 21:26 log.100000001

-rw-r--r--. 1 root root      380  9月 23 17:19 snapshot.100008484
となっており、

トランザクションログ自体は削除されていないように見えます。

log.100000001自体は1号機、2号機、3号機とも同じサイズ、同じ更新時間で存在しますので、

障害時に出力されたacceptedEpochとcurrentEpochが邪魔しているようにも見えるので

zookeeperについては詳しくない素人考えですが、削除してみたらどうかなぁとも思ったりもします。

centosはバージョン6ではありませんので、tmpwatchはありませんが、

バージョン7のsystemd-tmpfiles-clean.timerにより、ご指摘頂いた通り

tmpは以下は削除される可能性はありますので、dataDirの設定は変更しようと思います。

手順としては、

・実験として、3号機のzookeeperの停止、起動後、Jubatusプロキシを立ち上げてみる

・実験として、3号機のacceptedEpochとcurrentEpochを削除して後にJubatusプロキシを立ち上げてみる

を行った後、

・zookeeperの停止

・datadirを変更

・zookeeperの立ち上げ直し

・Jubatusプロキシの立ち上げてみる

の順でトライしてみようと思います。

以上の中で、私の方で思い違いなどあればご指摘くださいませ。

よろしくお願いいたします。

[Ryohei IMAMASU]

三田様

今増です。返信が遅くなってしまい、申し訳ありません。

トランザクションログは削除されていないということですが、いただいたログから判断できる範囲では、やはり、Jubatus に出ているログ（ZooKeeper にノードを作ることができない）からも、ZooKeeper の設定、環境に原因があるものと考えられます。

・zookeeperの停止

・datadirを変更

・zookeeperの立ち上げ直し

・Jubatusプロキシの立ち上げてみる

の順でトライしてみようと思います。

上記手順で問題ありません。

まずは 上記 の datadir を変更の上、トライしていただければと思います。

よろしくお願いいたします。

[yesmi...@gmail.com]

Jubatus Team 今増さま

三田です。

ご返信ありがとうございます。

先週、作業して解決しております。

> 実験として、3号機のzookeeperの停止、起動後、Jubatusプロキシを立ち上げてみる

最初の実験の「ただzookeeperを立ち上げ直す」だけで、

zookeeperは問題なく立ち上がり、Jubatusプロキシも立ち上がりました。

ただし、zookeeper_server.pidが削除されていたため終了時はkillにて強制終了し、

myidファイルも削除されていたため起動時は作成し直し立ち上げました。

両ファイルともsystemd-tmpfiles-clean.timerにより削除されたものと思われます。

zookeeperを立ち上げ直すだけで復旧してしまったので、

＞・実験として、3号機のacceptedEpochとcurrentEpochを削除して後にJubatusプロキシを立ち上げてみる

は行いませんでした。

これからすると、トランザクションログファイル自体が問題ではなかった？

pidファイル、myidファイルが削除された影響かとも考えましたが、

他の2台もpidファイル、myidファイルともに削除されていましたが、問題なく動作を続けていた。

いずれにしてもtmpディレクトリはよくないですね。

zookeeperは何も考えずサンプルの設定ファイルをコピーして使用していました。

トランザクションログの位置はうかつでした。

その後、予定通り3台ともトランザクションログの位置を変更いたしました。

お忙しい中、お時間を頂きありがとうございました。

ご確認・ご指摘ありがとうございました。