あめも

初心者インフラエンジニアの仕事や日常の事をそれとなく書いていくブログです

/var/log/zookeeper のログが多いと思ったらleaderだった

Apache ZooKeeperのログが多かった時のメモ

ZooKeeperとは

  • 「面倒な分散システムのコーディネートを支援するサービス」です(以下から引用)

oss.infoscience.co.jp

  • クラスタ環境で動作させる場合は、過半数の関係で3台からの奇数台で動作させるのがベストとのこと

参考にした記事

以下Qiita記事を参考に確認しました。

qiita.com

今回の構成

master01、master02、master03の3台でzookeeper-serverが動作しています。

leaderとfollowerの確認
  • 以下コマンドを実行して、表示された結果の Modeを見ると分かります
$ echo srvr | nc localhost 2181
  • 更に以下のコマンドでは接続中のclient情報も表示されました
$ echo stat | nc localhost 2181
確認結果

master01: follower

[root@master01 ~]# echo srvr | nc localhost 2181
Zookeeper version: 3.4.6-2950--1, built on 09/30/2015 17:44 GMT
Latency min/avg/max: 0/0/1565
Received: 1438388228
Sent: 1438388275
Connections: 200
Outstanding: 1
Zxid: 0xe684f40ec
Mode: follower
Node count: 20217

master02: follower

[root@master02 ~]# echo srvr | nc localhost 2181
Zookeeper version: 3.4.6-2950--1, built on 09/30/2015 17:44 GMT
Latency min/avg/max: 0/0/1123
Received: 748121494
Sent: 748121490
Connections: 138
Outstanding: 0
Zxid: 0xe640df008
Mode: follower
Node count: 20216


master03: leader

[root@master03 zookeeper]# echo srvr | nc localhost 2181
Zookeeper version: 3.4.6-2950--1, built on 09/30/2015 17:44 GMT
Latency min/avg/max: 0/0/1569
Received: 1202155859
Sent: 1202155861
Connections: 185
Outstanding: 0
Zxid: 0xe640db21e
Mode: leader
Node count: 20215

問題のログ

follower

1日数KB程度、多い時でも数十KB

-rw-r--r-- 1 root      root   1.8K 12月 29 00:50 2018 zookeeper.log.2018-11-09
-rw-r--r-- 1 root      root   1.3K 12月 29 00:50 2018 zookeeper.log.2018-12-29
-rw-r--r-- 1 root      root    22K  1月 20 00:22 2019 zookeeper.log.2019-01-20
-rw-r--r-- 1 root      root    15K  2月 20 12:15 2019 zookeeper.log.2019-02-04
-rw-r--r-- 1 root      root   7.6K  2月 20 18:17 2019 zookeeper.log.2019-02-20
-rw-r--r-- 1 root      root   7.4K  2月 22 18:44 2019 zookeeper.log.2019-02-22
-rw-r--r-- 1 root      root    15K  2月 23 20:06 2019 zookeeper.log
-rw-r--r-- 1 zookeeper hadoop  54M  2月 27 18:48 2019 zookeeper.out

ログの中身も特に変わったところは無し(長かったので冒頭だけ)

[root@master02 ~]# cat /var/log/zookeeper/zookeeper.log
2019-02-23 20:02:11,569 INFO org.apache.zookeeper.ZooKeeper: Client environment:zookeeper.version=3.4.6-2950--1, built
 on 09/30/2015 17:44 GMT
2019-02-23 20:02:11,588 INFO org.apache.zookeeper.ZooKeeper: Client environment:host.name=master02
2019-02-23 20:02:11,588 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.version=1.8.0_40
2019-02-23 20:02:11,588 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.vendor=Oracle Corporation
2019-02-23 20:02:11,588 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.home=/usr/jdk64/jdk1.8.0_40/jre
2019-02-23 20:02:11,588 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.class.path=/usr/hdp/2.3.2.0-2950/
leader

1ファイル約3GB強ありました

-rw-r--r-- 1 zookeeper hadoop 3.1G  2月 20 23:59 2019 zookeeper.log.2019-02-20
-rw-r--r-- 1 zookeeper hadoop 3.1G  2月 21 23:59 2019 zookeeper.log.2019-02-21
-rw-r--r-- 1 zookeeper hadoop 3.2G  2月 22 23:59 2019 zookeeper.log.2019-02-22
-rw-r--r-- 1 zookeeper hadoop 3.3G  2月 23 23:59 2019 zookeeper.log.2019-02-23
-rw-r--r-- 1 zookeeper hadoop 3.2G  2月 24 23:59 2019 zookeeper.log.2019-02-24
-rw-r--r-- 1 zookeeper hadoop 3.2G  2月 25 23:59 2019 zookeeper.log.2019-02-25
-rw-r--r-- 1 zookeeper hadoop 3.2G  2月 26 23:59 2019 zookeeper.log.2019-02-26
-rw-r--r-- 1 zookeeper hadoop 4.5M  2月 27 15:16 2019 zookeeper.out
-rw-r--r-- 1 zookeeper hadoop 2.8G  2月 27 20:48 2019 zookeeper.log

ログの中身はこんな感じ(follower側の/var/log/zookeeperで出力されているログはもしかしてzookeeper-clientのログ?)

2019-02-27 00:00:00,002 INFO org.apache.zookeeper.server.NIOServerCnxnFactory: Accepted socket connection from /10.120.121.152:5999
2019-02-27 00:00:00,008 INFO org.apache.zookeeper.server.PrepRequestProcessor: Processed session termination for sessionid: 0x26866b53a0e6a7d
2019-02-27 00:00:00,038 INFO org.apache.zookeeper.server.ZooKeeperServer: Client attempting to establish new session at /10.120.121.152:5999
2019-02-27 00:00:00,040 INFO org.apache.zookeeper.server.ZooKeeperServer: Established session 0x367f582c460ff34 with negotiated timeout 40000 for client /10.120.121.152:5999
2019-02-27 00:00:00,048 INFO org.apache.zookeeper.server.PrepRequestProcessor: Processed session termination for sessionid: 0x167f582c513c96a
2019-02-27 00:00:00,048 INFO org.apache.zookeeper.server.PrepRequestProcessor: Processed session termination for sessionid: 0x167f582c513c969
2019-02-27 00:00:00,049 INFO org.apache.zookeeper.server.PrepRequestProcessor: Processed session termination for sessionid: 0x367f582c460ff33
2019-02-27 00:00:00,049 INFO org.apache.zookeeper.server.NIOServerCnxn: Closed socket connection for client /10.120.121.153:8941 which had sessionid 0x367f582c460ff33
2019-02-27 00:00:00,050 INFO org.apache.zookeeper.server.PrepRequestProcessor: Processed session termination for sessionid: 0x367f582c460ff34
2019-02-27 00:00:00,051 INFO org.apache.zookeeper.server.NIOServerCnxn: Closed socket connection for client /10.120.121.152:5999 which had sessionid 0x367f582c460ff34

ZooKeeperを起動した当初はmaster02がleaderで、その時はログの量は特に目立っていなかったのですが、master03がleaderになってログの量が目立ち始めたので、何故こうなったのかは謎のままでした。

対処

log4jの設定変更でも行けると思いましたが、一旦cronで古いログを削除するように設定しました。

10 1 * * * root find /var/log/zookeeper -type f -mtime +30 -delete

何故ログの量が増えたのか、followerの/var/log/zookeeperに出力されているログはzookeeper-serverのログなのか、余裕があったら調べてみたいです。