Contents

Introduction

Check Exhibitor Service Status

Query Zookeeper Service

Zookeeper Log Files in a Live Setup

Zookeeper Log Files from Support-bundle (storfs)

Introduction

This document describes ZooKeeper, which is essentially a centralized service for distributed systems to a hierarchical key-value store. It is used to provide a distributed configuration service, synchronization service, and naming registry for large distributed systems. ZooKeeper's architecture supports high availability through redundant services. Clients can thus ask another ZooKeeper leader if the first fails to answer. ZooKeeper nodes store their data in a hierarchical namespace, much like a file system or a tree data structure. Clients can read from and write to the nodes and in this way have a shared configuration service. ZooKeeper can be viewed as an atomic broadcast system through which updates are totally ordered.

ZooKeeper offers these main features:

- Reliable system -The system is very reliable because it keeps working even if a node fails.

- Simple architecture - The architecture of ZooKeeper is quite simple; it uses a shared hierarchical namespace, which helps in process coordination.

- Fast processing - ZooKeeper is especially fast for read-dominant workloads.

- Scalable - The performance of ZooKeeper can be improved by the addition of nodes.

In HX, there is this specific implementation:

- The Service called exhibitor manages zookeeper startup/shutdown.

- Processes within the HX cluster are clients to Zookeeper and communicate over tcp port 2181 ex storfs, stmgr, and so on.

- Systems with more than five nodes will have some nodes in standalone. Systems with five nodes or less should never have a node in standalone.

- The minimum number of nodes required for Quorum = N/2 +1.

For example, for a three node cluster - N/2=1.5 Rounded off to 1 +1 =2 (Only one node failure can be tolerated)

For example, for a five node cluster - N/2=2.5 Rounded off to 2 +1 =3 (Only two node failures can be tolerated)

Since you only ever do five nodes for a ZK cluster, you only tolerate a maximum of two node failures for any number of nodes in the cluster. This is true of converged nodes.

Check Exhibitor Service Status

root@SpringpathControllerMSH7NHXRFL:/var/log/zookeeper# service exhibitor status

exhibitor start/running, process 4905

root@help:/var/log/springpath# ps -aux | grep -i exhibitor

root 12519 0.0 0.2 4690592 198892 ? Ssl May19 7:19 exhibitor -cp exhibitor.jar:/etc/exhibitor/ -Xmx256M -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/var/log/exhibitor_heap_dump_2019_05_19_22:19:48.hprof -Dlog4j.configuration=file:///etc/exhibitor/log4j.properties -Dspringpath.zkdownscript=/usr/share/springpath/storfs-misc/zkMonitor.sh -Djava.security.egd=file:/dev/./urandom -jar exhibitor.jar --hostname 10.197.252.100 -c file --fsconfigdir /etc/exhibitor --port 8180 --listenaddress 10.197.252.100

root@help:/var/log/springpath# pidof exhibitor

12519

Query Zookeeper Service

Zookeeper has a four letter command syntax that enables you to query status, list connections, number of znodes, and so on.

Check zookeeper status on local node - (ruok ==> Are you OK?. imok==>I am OK).

root@SpringpathControllerMSH7NHXRFL:/var/log/zookeeper# echo ruok|nc localhost 2181

imok

Check whether the zookeeper is a leader or follower.

root@SpringpathControllerMSH7NHXRFL:/var/log/zookeeper#  echo srvr | nc localhost 2181

Zookeeper version: 3.4.6--1, built on 06/16/2015 22:50 GMT

Latency min/avg/max: 0/0/101

Received: 213128515

Sent: 213164119

Connections: 6

Outstanding: 0

Zxid: 0xa000301d0

Mode: leader

Node count: 17090

root@SpringpathControllerMSH7NHXRFL:/var/log/zookeeper#  echo stat | nc localhost 2181

Zookeeper version: 3.4.6--1, built on 06/16/2015 22:50 GMT

Clients:

/192.168.5.161:56128[1](queued=0,recved=169146196,sent=169162634)

/192.168.5.161:38614[1](queued=0,recved=186015,sent=186017)

/192.168.5.164:44412[1](queued=0,recved=184398,sent=184399)

/192.168.5.164:44447[1](queued=0,recved=561168,sent=563034)

/127.0.0.1:60060[0](queued=0,recved=1,sent=0)

/192.168.5.161:58754[1](queued=0,recved=39233,sent=39261)

Latency min/avg/max: 0/0/101

Received: 213109927

Sent: 213145531

Connections: 6

Outstanding: 0

Zxid: 0xa000301d0

Mode: leader

Node count: 17090

root@SpringpathControllerMSH7NHXRFL:/var/log/zookeeper#  echo mntr | nc localhost 2181

zk_version    3.4.6--1, built on 06/16/2015 22:50 GMT

zk_avg_latency    0

zk_max_latency    101

zk_min_latency    0

zk_packets_received    213148668

zk_packets_sent    213184272

zk_num_alive_connections    6

zk_outstanding_requests    0

zk_server_state    leader

zk_znode_count    17090

zk_watch_count    4305

zk_ephemerals_count    20

zk_approximate_data_size    1831768

zk_open_file_descriptor_count    43

zk_max_file_descriptor_count    4096

zk_followers    3

zk_synced_followers    3

zk_pending_syncs    0

Check the Zookeeper configuration:

root@SpringpathControllerMSH7NHXRFL:/var/log/zookeeper#  echo conf | nc localhost 2181

clientPort=2181

dataDir=/var/zookeeper/version-2

dataLogDir=/var/zookeeper/version-2

tickTime=3000

maxClientCnxns=60

minSessionTimeout=6000

maxSessionTimeout=60000

serverId=3

initLimit=10

syncLimit=3

electionAlg=3

electionPort=3888

quorumPort=2888

peerType=0

Zookeeper Log Files in a Live Setup

If there are any issues in Zookeeper services, these log files will help to find traces:

- /var/log/zookeeper/zookeeper* - Maintains archived logs, helpful search keywords  WARN, ERROR, Goodbye, Leader , and so on.

- /var/log/springpath/zk-*

- /var/log/springpath/exhibitor.log

root@SpringpathControllerMSH7NHXRFL:/var/log/zookeeper# grep -i leader /var/log/zookeeper/zookeeper.log*

/var/log/zookeeper/zookeeper.log.7:2016-10-14 22:59:26,088 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Leader@60] - TCP NoDelay set to: true

/var/log/zookeeper/zookeeper.log.7:2016-10-14 22:59:26,099 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Leader@358] - LEADING - LEADER ELECTION TOOK - 354

/var/log/zookeeper/zookeeper.log.7:2016-10-14 22:59:26,120 [myid:3] - INFO  [LearnerHandler-/192.168.5.164:36487:LearnerHandler@522] - Received NEWLEADER-ACK message from 0

/var/log/zookeeper/zookeeper.log.7:2016-10-14 22:59:26,120 [myid:3] - INFO  [LearnerHandler-/192.168.5.163:43451:LearnerHandler@522] - Received NEWLEADER-ACK message from 1

/var/log/zookeeper/zookeeper.log.7:2016-10-14 22:59:26,120 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Leader@943] - Have quorum of supporters, sids: [ 0,1,3 ]; starting up and setting last processed zxid: 0x100000000

/var/log/zookeeper/zookeeper.log.7:2016-10-14 22:59:26,272 [myid:3] - INFO  [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message format version), 3 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 2 (n.sid), 0x0 (n.peerEpoch) LEADING (my state)

/var/log/zookeeper/zookeeper.log.7:2016-10-14 22:59:26,291 [myid:3] - INFO  [LearnerHandler-/192.168.5.162:48778:LearnerHandler@486] - Sending snapshot last zxid of peer is 0x0  zxid of leader is 0x100000000sent zxid of db as 0x100000000

/var/log/zookeeper/zookeeper.log.7:2016-10-14 22:59:26,298 [myid:3] - INFO  [LearnerHandler-/192.168.5.162:48778:LearnerHandler@522] - Received NEWLEADER-ACK message from 2

root@SpringpathControllerMSH7NHXRFL:/var/log/zookeeper# grep -i warn /var/log/zookeeper/zookeeper.log*

/var/log/zookeeper/zookeeper.log.7:2016-10-14 22:46:30,354 [myid:] - WARN  [main:QuorumPeerMain@113] - Either no config or no quorum defined in config, running  in standalone mode

/var/log/zookeeper/zookeeper.log.7:2016-10-14 22:52:55,238 [myid:] - WARN  [main:QuorumPeerMain@113] - Either no config or no quorum defined in config, running  in standalone mode

root@SpringpathControllerMSH7NHXRFL:/var/log/zookeeper# grep -i goodbye /var/log/zookeeper/zookeeper.log*

/var/log/zookeeper/zookeeper.log.1:2017-01-23 03:55:50,429 [myid:3] - WARN  [LearnerHandler-/192.168.5.163:44118:LearnerHandler@646] - ******* GOODBYE /192.168.5.163:44118 ********

/var/log/zookeeper/zookeeper.log.1:2017-01-24 23:30:14,956 [myid:3] - WARN  [LearnerHandler-/192.168.5.164:44720:LearnerHandler@646] - ******* GOODBYE /192.168.5.164:44720 ********

/var/log/zookeeper/zookeeper.log.3:2016-12-01 23:45:22,510 [myid:3] - WARN  [LearnerHandler-/192.168.5.164:44051:LearnerHandler@646] - ******* GOODBYE /192.168.5.164:44051 ********

/var/log/zookeeper/zookeeper.log.3:2016-12-08 00:36:37,752 [myid:3] - WARN  [LearnerHandler-/192.168.5.162:46577:LearnerHandler@646] - ******* GOODBYE /192.168.5.162:46577 ********

/var/log/zookeeper/zookeeper.log.4:2016-11-22 23:45:30,957 [myid:3] - WARN  [LearnerHandler-/192.168.5.163:49016:LearnerHandler@646] - ******* GOODBYE /192.168.5.163:49016 ********

/var/log/zookeeper/zookeeper.log.4:2016-11-23 00:03:59,397 [myid:3] - WARN  [LearnerHandler-/192.168.5.164:45952:LearnerHandler@646] - ******* GOODBYE /192.168.5.164:45952 ********

/var/log/zookeeper/zookeeper.log.4:2016-12-01 22:51:00,538 [myid:3] - WARN  [LearnerHandler-/192.168.5.163:45284:LearnerHandler@646] - ******* GOODBYE /192.168.5.163:45284 ********

/var/log/zookeeper/zookeeper.log.5:2016-11-10 23:39:47,477 [myid:3] - WARN  [LearnerHandler-/192.168.5.163:43576:LearnerHandler@646] - ******* GOODBYE /192.168.5.163:43576 ********

/var/log/zookeeper/zookeeper.log.5:2016-11-11 00:49:39,782 [myid:3] - WARN  [LearnerHandler-/192.168.5.164:35219:LearnerHandler@646] - ******* GOODBYE /192.168.5.164:35219 ********

Some Sample Logs - Zookeeper Logging Election

2017-01-22 23:47:29,427 [myid:3] - INFO  [Thread-2:QuorumCnxManager$Listener@504] - My election bind port: /192.168.5.161:3888

2017-01-22 23:47:29,435 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:QuorumPeer@714] - LOOKING

2017-01-22 23:47:29,438 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@815] - New election. My id =  3, proposed zxid=0x9000a6b4d

2017-01-22 23:47:29,443 [myid:3] - INFO  [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message format version), 2 (n.leader), 0x800055ea0 (n.zxid), 0x1 (n.round), FOLLOWING (n.state), 0 (n.sid), 0x9 (n.peerEpoch) LOOKING (my state)

2017-01-22 23:47:29,444 [myid:3] - INFO  [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message format version), 2 (n.leader), 0x800055ea0 (n.zxid), 0x1 (n.round), FOLLOWING (n.state), 1 (n.sid), 0x9 (n.peerEpoch) LOOKING (my state)

2017-01-22 23:47:29,444 [myid:3] - INFO  [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message format version), 3 (n.leader), 0x9000a6b4d (n.zxid), 0x1 (n.round), LOOKING (n.state), 3 (n.sid), 0x9 (n.peerEpoch) LOOKING (my state)

2017-01-22 23:47:29,444 [myid:3] - INFO  [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message format version), 2 (n.leader), 0x800055ea0 (n.zxid), 0x1 (n.round), FOLLOWING (n.state), 1 (n.sid), 0x9 (n.peerEpoch) LOOKING (my state)

2017-01-22 23:47:29,445 [myid:3] - INFO  [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message format version), 2 (n.leader), 0x800055ea0 (n.zxid), 0x1 (n.round), LEADING (n.state), 2 (n.sid), 0x9 (n.peerEpoch) LOOKING (my state)

2017-01-22 23:47:29,445 [myid:3] - INFO  [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message format version), 2 (n.leader), 0x800055ea0 (n.zxid), 0x1 (n.round), FOLLOWING (n.state), 0 (n.sid), 0x9 (n.peerEpoch) LOOKING (my state)

2017-01-22 23:47:29,446 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:QuorumPeer@784] - FOLLOWING

2017-01-22 23:47:29,449 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Learner@86] - TCP NoDelay set to: true

2017-01-22 23:47:29,449 [myid:3] - INFO  [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message format version), 2 (n.leader), 0x800055ea0 (n.zxid), 0x1 (n.round), LEADING (n.state), 2 (n.sid), 0x9 (n.peerEpoch) FOLLOWING (my state)

2017-01-22 23:47:29,660 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server environment:zookeeper.version=3.4.6--1, built on 06/16/2015 22:50 GMT

2017-01-22 23:47:29,661 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server environment:host.name=SpringpathControllerMSH7NHXRFL

2017-01-22 23:47:29,661 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server environment:java.version=1.7.0_79

2017-01-22 23:47:29,661 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server environment:java.vendor=Oracle Corporation

2017-01-22 23:47:29,661 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server environment:java.home=/usr/lib/jvm/java-7-openjdk-amd64/jre

2017-01-22 23:47:29,661 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server environment:java.class.path=/usr/share/zookeeper/bin/../build/classes:/usr/share/zookeeper/bin/../build/lib/*.jar:/usr/share/zookeeper/bin/../lib/slf4j-log4j12-1.6.1.jar:/usr/share/zookeeper/bin/../lib/slf4j-api-1.6.1.jar:/usr/share/zookeeper/bin/../lib/netty-3.7.0.Final.jar:/usr/share/zookeeper/bin/../lib/log4j-1.2.16.jar:/usr/share/zookeeper/bin/../lib/jline-0.9.94.jar:/usr/share/zookeeper/bin/../zookeeper-3.4.6.jar:/usr/share/zookeeper/bin/../src/java/lib/*.jar:/usr/share/zookeeper/bin/../conf:

2017-01-22 23:47:29,661 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib

2017-01-22 23:47:29,661 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server environment:java.io.tmpdir=/tmp

2017-01-22 23:47:29,661 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server environment:java.compiler=<NA>

2017-01-22 23:47:29,661 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server environment:os.name=Linux

2017-01-22 23:47:29,661 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server environment:os.arch=amd64

2017-01-22 23:47:29,661 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server environment:os.version=3.2.0-58-generic

2017-01-22 23:47:29,661 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server environment:user.name=root

2017-01-22 23:47:29,661 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server environment:user.home=/root

2017-01-22 23:47:29,662 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server environment:user.dir=/usr/share/zookeeper

2017-01-22 23:47:29,662 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@162] - Created server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 60000 datadir /var/zookeeper/version-2 snapdir /var/zookeeper/version-2

2017-01-22 23:47:29,663 [myid:3] - INFO  [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Follower@63] - FOLLOWING - LEADER ELECTION TOOK - 226

root@SpringpathControllerMSH7NHXRFL:/var/log/springpath# cat   zk-debug-storfs.log

2017-01-22 23:47:18,702:5866(0x7fd1f7ef5700):ZOO_INFO@check_events@1760: initiated connection to server [192.168.5.163:2181]

2017-01-22 23:47:18,704:5866(0x7fd1f7ef5700):ZOO_INFO@check_events@1807: session establishment complete on server [192.168.5.163:2181], sessionId=0x159165ff6310005, negotiated timeout=17001

2017-01-22 23:47:18,704:5866(0x7fd1f76f4700):ZOO_INFO@process_completions@2170: Calling a watcher for node s], type = s

2017-01-23 01:50:16,809:5866(0x7fd1f7ef5700):ZOO_ERROR@handle_socket_error_msg@1778: Socket [192.168.5.163:2181] zk retcode=-4, errno=112(Host is down): failed while receiving a server response

2017-01-23 01:50:16,818:5866(0x7fd1f76f4700):ZOO_INFO@process_completions@2170: Calling a watcher for node s], type = s

2017-01-23 01:50:16,818:5866(0x7fd1f7ef5700):ZOO_INFO@check_events@1760: initiated connection to server [192.168.5.164:2181]

2017-01-23 01:50:16,818:5866(0x7fd1f7ef5700):ZOO_ERROR@handle_socket_error_msg@1778: Socket [192.168.5.164:2181] zk retcode=-4, errno=112(Host is down): failed while receiving a server response

2017-01-23 01:50:17,819:5866(0x7fd1f7ef5700):ZOO_ERROR@handle_socket_error_msg@1740: Socket [192.168.5.162:2181] zk retcode=-4, errno=115(Operation now in progress): poll refused to accept read/write from the client

root@help:/var/log/springpath# cat zkEvents.log

INFO:ZkEvents:Send changes to listeners

INFO:EventDB:Received message{"timestamp": 1559200009008, "description": "Cluster policy compliance is satisfied", "id": "ClusterPolicyComplianceSatisfiedEvent"}

DEBUG:kazoo.client:Received EVENT: Watch(type=3, state=3, path=u'/zkEvents/lastModificationTime')

DEBUG:kazoo.client:Sending request(xid=42): GetData(path='/zkEvents/lastModificationTime', watcher=<bound method DataWatch._watcher of <kazoo.recipe.watchers.DataWatch object at 0x7fec80ffd0d0>>)

DEBUG:kazoo.client:Received response(xid=42): ('{"timestamp": 1559200009009, "description": "Cluster is healthy", "id": "ClusterHealthNormalEvent"}', ZnodeStat(czxid=4294968021, mzxid=85899377486, ctime=1543045592975, mtime=1559200010730, version=465, cversion=0, aversion=0, ephemeralOwner=0, dataLength=99, numChildren=0, pzxid=4294968021))

INFO:ZkEvents:Version: 465, data: {"timestamp": 1559200009009, "description": "Cluster is healthy", "id": "ClusterHealthNormalEvent"}

INFO:ZkEvents:Send changes to listeners

INFO:EventDB:Received message{"timestamp": 1559200009009, "description": "Cluster is healthy", "id": "ClusterHealthNormalEvent"}

INFO:EventDB:Client(38) disconnected

INFO:EventDB:New client connected and was given id 39

INFO:EventDB:Client(39) disconnected

root@SpringpathControllerPZTMTRSH7K:/var/log/springpath# tail exhibitor.log

05-20 05:28:52.223 INFO org.mortbay.log - Started SocketConnector@10.197.252.99:8180

05-20 05:29:20.106 INFO com.netflix.exhibitor.core.activity.ActivityLog - State: down

05-20 05:29:20.106 INFO com.netflix.exhibitor.core.activity.ActivityLog - Attempting to stop instance

05-20 05:29:20.106 INFO com.netflix.exhibitor.core.activity.ActivityLog - Attempting to start/restart ZooKeeper

05-20 05:29:20.328 INFO com.netflix.exhibitor.core.activity.ActivityLog - jps didn't find instance - assuming ZK is not running

05-20 05:29:20.347 INFO com.netflix.exhibitor.core.activity.ActivityLog - Process started via: /usr/share/zookeeper/bin/zkServer.sh

05-20 05:29:20.353 ERROR com.netflix.exhibitor.core.activity.ActivityLog - ZooKeeper Server: ZooKeeper JMX enabled by default

05-20 05:29:20.353 ERROR com.netflix.exhibitor.core.activity.ActivityLog - ZooKeeper Server: Using config: /usr/share/zookeeper/bin/../conf/zoo.cfg

05-20 05:29:21.366 INFO com.netflix.exhibitor.core.activity.ActivityLog - ZooKeeper Server: Starting zookeeper ... STARTED

05-20 05:29:50.128 INFO com.netflix.exhibitor.core.activity.ActivityLog - State: serving

Zookeeper Log Files from Support-bundle (storfs)

In a support-bundle, these are important files to look at:

zookeeper.log                      /var/log/zookeeper

zk-storfs.log                      /var/log/springpath

echo_stat_|nc_localhost_2181.out   under cmds_output