The setup was running for two weeks without any issue. Since its a production, we didn't do any restart brokers. After facing the issue, we have restarted the broker 2, and then it was working fine. But we would like to know the root cause of the issue. ... View more

Yes. In server.log the connection between kafka broker node 2 with zookeeper node 1 got timed out as i mentioned in the description. It happened only with 2nd broker. server.log (kafka2) [2018-07-18 23:45:11,411] INFO [GroupMetadataManager brokerId=2] Removed 0 expired offsets in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager) [2018-07-18 23:55:11,411] INFO [GroupMetadataManager brokerId=2] Removed 0 expired offsets in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager) [2018-07-19 00:05:11,411] INFO [GroupMetadataManager brokerId=2] Removed 0 expired offsets in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager) [2018-07-19 00:15:11,411] INFO [GroupMetadataManager brokerId=2] Removed 0 expired offsets in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager) [2018-07-19 00:25:11,411] INFO [GroupMetadataManager brokerId=2] Removed 0 expired offsets in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager) [2018-07-19 00:35:11,411] INFO [GroupMetadataManager brokerId=2] Removed 0 expired offsets in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager) [2018-07-19 00:37:19,435] WARN Client session timed out, have not heard from server in 4002ms for sessionid 0x16439d7fab80006 (org.apache.zookeeper.ClientCnxn) [2018-07-19 00:37:19,435] INFO Client session timed out, have not heard from server in 4002ms for sessionid 0x16439d7fab80006, closing socket connection and attempting reconnect (org.apache.zookeeper.ClientCnxn) [2018-07-19 00:37:20,143] INFO Opening socket connection to server zk1/zk1:2181. Will not attempt to authenticate using SASL (unknown error) (org.apache.zookeeper.ClientCnxn) [2018-07-19 00:37:20,144] INFO Socket connection established to zk1/zk1:2181, initiating session (org.apache.zookeeper.ClientCnxn) [2018-07-19 00:37:20,146] WARN Unable to reconnect to ZooKeeper service, session 0x16439d7fab80006 has expired (org.apache.zookeeper.ClientCnxn) [2018-07-19 00:37:20,146] INFO Unable to reconnect to ZooKeeper service, session 0x16439d7fab80006 has expired, closing socket connection (org.apache.zookeeper.ClientCnxn) [2018-07-19 00:37:20,148] INFO [ZooKeeperClient] Session expired. (kafka.zookeeper.ZooKeeperClient) [2018-07-19 00:37:20,148] INFO EventThread shut down for session: 0x16439d7fab80006 (org.apache.zookeeper.ClientCnxn) [2018-07-19 00:37:20,149] INFO [ZooKeeperClient] Initializing a new session to zk1:2181,zk2:3181,zk3:4181. (kafka.zookeeper.ZooKeeperClient) [2018-07-19 00:37:20,149] INFO Initiating client connection, connectString=zk1:2181,zk2:3181,zk3:4181 sessionTimeout=6000 watcher=kafka.zookeeper.ZooKeeperClient$ZooKeeperClientWatcher$@63021689 (org.apache.zookeeper.ZooKeeper) [2018-07-19 00:37:20,150] INFO Opening socket connection to server zk2/zk2:3181. Will not attempt to authenticate using SASL (unknown error) (org.apache.zookeeper.ClientCnxn) [2018-07-19 00:37:20,153] INFO Creating /brokers/ids/2 (is it secure? false) (kafka.zk.KafkaZkClient) [2018-07-19 00:37:22,151] WARN Client session timed out, have not heard from server in 2002ms for sessionid 0x0 (org.apache.zookeeper.ClientCnxn) [2018-07-19 00:37:22,151] INFO Client session timed out, have not heard from server in 2002ms for sessionid 0x0, closing socket connection and attempting reconnect (org.apache.zookeeper.ClientCnxn) [2018-07-19 00:37:22,252] INFO Opening socket connection to server zk1/zk1:2181. Will not attempt to authenticate using SASL (unknown error) (org.apache.zookeeper.ClientCnxn) [2018-07-19 00:37:22,253] INFO Socket connection established to zk1/zk1:2181, initiating session (org.apache.zookeeper.ClientCnxn) [2018-07-19 00:37:22,254] INFO [ZooKeeperClient] Waiting until connected. (kafka.zookeeper.ZooKeeperClient) [2018-07-19 00:37:22,254] INFO [ZooKeeperClient] Waiting until connected. (kafka.zookeeper.ZooKeeperClient) [2018-07-19 00:37:22,254] INFO Session establishment complete on server zk1/zk1:2181, sessionid = 0x16439d7f4f92d6c, negotiated timeout = 6000 (org.apache.zookeeper.ClientCnxn) [2018-07-19 00:37:22,254] INFO [ZooKeeperClient] Connected. (kafka.zookeeper.ZooKeeperClient) [2018-07-19 00:37:22,254] INFO [ZooKeeperClient] Connected. (kafka.zookeeper.ZooKeeperClient) [2018-07-19 00:37:22,257] INFO Result of znode creation at /brokers/ids/2 is: OK (kafka.zk.KafkaZkClient) [2018-07-19 00:37:22,257] INFO Registered broker 2 at path /brokers/ids/2 with addresses: ArrayBuffer(EndPoint(kafka2,9092,ListenerName(PLAINTEXT),PLAINTEXT)) (kafka.zk.KafkaZkClient) [2018-07-19 00:37:22,259] INFO Creating /controller (is it secure? false) (kafka.zk.KafkaZkClient) [2018-07-19 00:37:22,262] INFO Result of znode creation at /controller is: OK (kafka.zk.KafkaZkClient) Zookeeper2 log [2018-07-19 00:36:53,241] INFO Processed session termination for sessionid: 0x16439d7faba2d6c (org.apache.zookeeper.server.PrepRequestProcessor) [2018-07-19 00:36:53,241] INFO Closed socket connection for client /consulApp:42436 which had sessionid 0x16439d7faba2d6c (org.apache.zookeeper.server.NIOServerCnxn) [2018-07-19 00:37:03,315] INFO Accepted socket connection from /consulApp:42528 (org.apache.zookeeper.server.NIOServerCnxnFactory) [2018-07-19 00:37:03,315] INFO Client attempting to establish new session at /consulApp:42528 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:03,316] INFO Established session 0x16439d7faba2d6d with negotiated timeout 10000 for client /consulApp:42528 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:03,318] INFO Processed session termination for sessionid: 0x16439d7faba2d6d (org.apache.zookeeper.server.PrepRequestProcessor) [2018-07-19 00:37:03,319] INFO Closed socket connection for client /consulApp:42528 which had sessionid 0x16439d7faba2d6d (org.apache.zookeeper.server.NIOServerCnxn) [2018-07-19 00:37:13,390] INFO Accepted socket connection from /consulApp:42622 (org.apache.zookeeper.server.NIOServerCnxnFactory) [2018-07-19 00:37:13,390] INFO Client attempting to establish new session at /consulApp:42622 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:13,392] INFO Established session 0x16439d7faba2d6e with negotiated timeout 10000 for client /consulApp:42622 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:13,393] INFO Processed session termination for sessionid: 0x16439d7faba2d6e (org.apache.zookeeper.server.PrepRequestProcessor) [2018-07-19 00:37:13,394] INFO Closed socket connection for client /consulApp:42622 which had sessionid 0x16439d7faba2d6e (org.apache.zookeeper.server.NIOServerCnxn) [2018-07-19 00:37:21,001] INFO Expiring session 0x16439d7fab80003, timeout of 6000ms exceeded (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:21,001] INFO Processed session termination for sessionid: 0x16439d7fab80003 (org.apache.zookeeper.server.PrepRequestProcessor) [2018-07-19 00:37:24,000] INFO Expiring session 0x16439d7fab80006, timeout of 6000ms exceeded (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:24,000] INFO Expiring session 0x16439d7fab8004c, timeout of 6000ms exceeded (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:24,000] INFO Processed session termination for sessionid: 0x16439d7fab80006 (org.apache.zookeeper.server.PrepRequestProcessor) [2018-07-19 00:37:24,001] INFO Processed session termination for sessionid: 0x16439d7fab8004c (org.apache.zookeeper.server.PrepRequestProcessor) [2018-07-19 00:45:44,047] WARN fsync-ing the write ahead log in SyncThread:0 took 503045ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide (org.apache.zookeeper.server.persistence.FileTxnLog) [2018-07-19 00:45:44,047] INFO Closed socket connection for client /kafka3:53822 which had sessionid 0x16439d7fab80003 (org.apache.zookeeper.server.NIOServerCnxn) [2018-07-19 00:45:44,049] INFO Closed socket connection for client /kafka2:57978 which had sessionid 0x16439d7fab80006 (org.apache.zookeeper.server.NIOServerCnxn) [2018-07-19 00:45:44,049] INFO Closed socket connection for client /kafka1:48862 which had sessionid 0x16439d7fab8004c (org.apache.zookeeper.server.NIOServerCnxn) [2018-07-19 00:45:51,321] INFO Accepted socket connection from /consulApp:47256 (org.apache.zookeeper.server.NIOServerCnxnFactory) [2018-07-19 00:45:51,322] INFO Client attempting to establish new session at /consulApp:47256 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:45:51,323] INFO Established session 0x16439d7faba2d6f with negotiated timeout 10000 for client /consulApp:47256 (org.apache.zookeeper.server.ZooKeeperServer) zookeeper1 log [2018-07-19 00:36:43,149] INFO Processed session termination for sessionid: 0x16439d7f4f92d68 (org.apache.zookeeper.server.PrepRequestProcessor) [2018-07-19 00:36:43,150] INFO Closed socket connection for client /consulApp:42572 which had sessionid 0x16439d7f4f92d68 (org.apache.zookeeper.server.NIOServerCnxn) [2018-07-19 00:36:53,224] INFO Accepted socket connection from /consulApp:42664 (org.apache.zookeeper.server.NIOServerCnxnFactory) [2018-07-19 00:36:53,225] INFO Client attempting to establish new session at /consulApp:42664 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:36:53,226] INFO Established session 0x16439d7f4f92d69 with negotiated timeout 10000 for client /consulApp:42664 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:36:53,228] INFO Processed session termination for sessionid: 0x16439d7f4f92d69 (org.apache.zookeeper.server.PrepRequestProcessor) [2018-07-19 00:36:53,228] INFO Closed socket connection for client /consulApp:42664 which had sessionid 0x16439d7f4f92d69 (org.apache.zookeeper.server.NIOServerCnxn) [2018-07-19 00:37:03,301] INFO Accepted socket connection from /consulApp:42756 (org.apache.zookeeper.server.NIOServerCnxnFactory) [2018-07-19 00:37:03,301] INFO Client attempting to establish new session at /consulApp:42756 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:03,302] INFO Established session 0x16439d7f4f92d6a with negotiated timeout 10000 for client /consulApp:42756 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:03,304] INFO Processed session termination for sessionid: 0x16439d7f4f92d6a (org.apache.zookeeper.server.PrepRequestProcessor) [2018-07-19 00:37:03,305] INFO Closed socket connection for client /consulApp:42756 which had sessionid 0x16439d7f4f92d6a (org.apache.zookeeper.server.NIOServerCnxn) [2018-07-19 00:37:13,379] INFO Accepted socket connection from /consulApp:42850 (org.apache.zookeeper.server.NIOServerCnxnFactory) [2018-07-19 00:37:13,379] INFO Client attempting to establish new session at /consulApp:42850 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:13,380] INFO Established session 0x16439d7f4f92d6b with negotiated timeout 10000 for client /consulApp:42850 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:13,382] INFO Processed session termination for sessionid: 0x16439d7f4f92d6b (org.apache.zookeeper.server.PrepRequestProcessor) [2018-07-19 00:37:13,383] INFO Closed socket connection for client /consulApp:42850 which had sessionid 0x16439d7f4f92d6b (org.apache.zookeeper.server.NIOServerCnxn) [2018-07-19 00:37:20,144] INFO Accepted socket connection from /kafka2:33496 (org.apache.zookeeper.server.NIOServerCnxnFactory) [2018-07-19 00:37:20,145] INFO Client attempting to renew session 0x16439d7fab80006 at /kafka2:33496 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:20,145] INFO Invalid session 0x16439d7fab80006 for client /kafka2:33496, probably expired (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:20,145] INFO Closed socket connection for client /kafka2:33496 which had sessionid 0x16439d7fab80006 (org.apache.zookeeper.server.NIOServerCnxn) [2018-07-19 00:37:22,253] INFO Accepted socket connection from /kafka2:33500 (org.apache.zookeeper.server.NIOServerCnxnFactory) [2018-07-19 00:37:22,253] INFO Client attempting to establish new session at /kafka2:33500 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:22,254] INFO Established session 0x16439d7f4f92d6c with negotiated timeout 6000 for client /kafka2:33500 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:22,307] INFO Got user-level KeeperException when processing sessionid:0x16439d7f4f92d6c type:delete cxid:0x14 zxid:0x45b5d txntype:-1 reqpath:n/a Error Path:/admin/preferred_replica_election Error:KeeperErrorCode = NoNode for /admin/preferred_replica_election (org.apache.zookeeper.server.PrepRequestProcessor) [2018-07-19 00:37:23,456] INFO Accepted socket connection from /consulApp:42942 (org.apache.zookeeper.server.NIOServerCnxnFactory) [2018-07-19 00:37:23,456] INFO Client attempting to establish new session at /consulApp:42942 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:23,457] INFO Established session 0x16439d7f4f92d6d with negotiated timeout 10000 for client /consulApp:42942 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:23,459] INFO Processed session termination for sessionid: 0x16439d7f4f92d6d (org.apache.zookeeper.server.PrepRequestProcessor) [2018-07-19 00:37:23,460] INFO Closed socket connection for client /consulApp:42942 which had sessionid 0x16439d7f4f92d6d (org.apache.zookeeper.server.NIOServerCnxn) [2018-07-19 00:37:33,531] INFO Accepted socket connection from /consulApp:43034 (org.apache.zookeeper.server.NIOServerCnxnFactory) [2018-07-19 00:37:33,531] INFO Client attempting to establish new session at /consulApp:43034 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:33,533] INFO Established session 0x16439d7f4f92d6e with negotiated timeout 10000 for client /consulApp:43034 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:33,534] INFO Processed session termination for sessionid: 0x16439d7f4f92d6e (org.apache.zookeeper.server.PrepRequestProcessor) [2018-07-19 00:37:33,535] INFO Closed socket connection for client /consulApp:43034 which had sessionid 0x16439d7f4f92d6e (org.apache.zookeeper.server.NIOServerCnxn) [2018-07-19 00:37:43,606] INFO Accepted socket connection from /consulApp:43128 (org.apache.zookeeper.server.NIOServerCnxnFactory) [2018-07-19 00:37:43,606] INFO Client attempting to establish new session at /consulApp:43128 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:43,608] INFO Established session 0x16439d7f4f92d6f with negotiated timeout 10000 for client /consulApp:43128 (org.apache.zookeeper.server.ZooKeeperServer) [2018-07-19 00:37:43,608] INFO Processed session termination for sessionid: 0x16439d7f4f92d6f (org.apache.zookeeper.server.PrepRequestProcessor) [2018-07-19 00:37:43,609] INFO Closed socket connection for client /consulApp:43128 which had sessionid 0x16439d7f4f92d6f (org.apache.zookeeper.server.NIOServerCnxn) [2018-07-19 00:37:53,692] INFO Accepted socket connection from /consulApp:43216 (org.apache.zookeeper.server.NIOServerCnxnFactory) [2018-07-19 00:37:53,692] INFO Client attempting to establish new session at /consulApp:43216 (org.apache.zookeeper.server.ZooKeeperServer) ... View more

Thanks for responding. Controller Log: [2018-07-19 00:37:20,150] DEBUG [Controller id=2] Unregister BrokerModifications handler for Set() (kafka.controller.KafkaController) [2018-07-19 00:37:20,151] INFO [PartitionStateMachine controllerId=2] Stopped partition state machine (kafka.controller.PartitionStateMachine) [2018-07-19 00:37:20,152] INFO [ReplicaStateMachine controllerId=2] Stopped replica state machine (kafka.controller.ReplicaStateMachine) [2018-07-19 00:37:20,153] INFO [Controller id=2] Resigned (kafka.controller.KafkaController) [2018-07-19 00:37:22,262] INFO [Controller id=2] 2 successfully elected as the controller (kafka.controller.KafkaController) [2018-07-19 00:37:22,263] INFO [Controller id=2] Reading controller epoch from ZooKeeper (kafka.controller.KafkaController) [2018-07-19 00:37:22,264] INFO [Controller id=2] Initialized controller epoch to 6 and zk version 5 (kafka.controller.KafkaController) [2018-07-19 00:37:22,264] INFO [Controller id=2] Incrementing controller epoch in ZooKeeper (kafka.controller.KafkaController) [2018-07-19 00:37:22,266] INFO [Controller id=2] Epoch incremented to 7 (kafka.controller.KafkaController) [2018-07-19 00:37:22,266] INFO [Controller id=2] Registering handlers (kafka.controller.KafkaController) [2018-07-19 00:37:22,268] INFO [Controller id=2] Deleting log dir event notifications (kafka.controller.KafkaController) [2018-07-19 00:37:22,269] INFO [Controller id=2] Deleting isr change notifications (kafka.controller.KafkaController) [2018-07-19 00:37:22,270] INFO [Controller id=2] Initializing controller context (kafka.controller.KafkaController) [2018-07-19 00:37:22,274] DEBUG [Controller id=2] Register BrokerModifications handler for Set(2) (kafka.controller.KafkaController) [2018-07-19 00:37:22,279] DEBUG [Channel manager on controller 2]: Controller 2 trying to connect to broker 2 (kafka.controller.ControllerChannelManager) [2018-07-19 00:37:22,282] INFO [RequestSendThread controllerId=2] Starting (kafka.controller.RequestSendThread) [2018-07-19 00:37:22,283] INFO [Controller id=2] Partitions being reassigned: Map() (kafka.controller.KafkaController) [2018-07-19 00:37:22,283] INFO [Controller id=2] Currently active brokers in the cluster: Set(2) (kafka.controller.KafkaController) [2018-07-19 00:37:22,284] INFO [Controller id=2] Currently shutting brokers in the cluster: Set() (kafka.controller.KafkaController) [2018-07-19 00:37:22,284] INFO [Controller id=2] Current list of topics in the cluster: Set() (kafka.controller.KafkaController) [2018-07-19 00:37:22,284] INFO [Controller id=2] Fetching topic deletions in progress (kafka.controller.KafkaController) [2018-07-19 00:37:22,286] INFO [Controller id=2] List of topics to be deleted: (kafka.controller.KafkaController) [2018-07-19 00:37:22,286] INFO [Controller id=2] List of topics ineligible for deletion: (kafka.controller.KafkaController) [2018-07-19 00:37:22,286] INFO [Controller id=2] Initializing topic deletion manager (kafka.controller.KafkaController) [2018-07-19 00:37:22,287] INFO [Controller id=2] Sending update metadata request (kafka.controller.KafkaController) [2018-07-19 00:37:22,291] INFO [ReplicaStateMachine controllerId=2] Initializing replica state (kafka.controller.ReplicaStateMachine) [2018-07-19 00:37:22,292] INFO [RequestSendThread controllerId=2] Controller 2 connected to x.x.x.x:9092 (id: 2 rack: null) for sending state change requests (kafka.controller.RequestSendThread) [2018-07-19 00:37:22,292] INFO [ReplicaStateMachine controllerId=2] Triggering online replica state changes (kafka.controller.ReplicaStateMachine) [2018-07-19 00:37:22,298] INFO [ReplicaStateMachine controllerId=2] Started replica state machine with initial state -> Map() (kafka.controller.ReplicaStateMachine) [2018-07-19 00:37:22,299] INFO [PartitionStateMachine controllerId=2] Initializing partition state (kafka.controller.PartitionStateMachine) [2018-07-19 00:37:22,299] INFO [PartitionStateMachine controllerId=2] Triggering online partition state changes (kafka.controller.PartitionStateMachine) [2018-07-19 00:37:22,301] INFO [PartitionStateMachine controllerId=2] Started partition state machine with initial state -> Map() (kafka.controller.PartitionStateMachine) [2018-07-19 00:37:22,302] INFO [Controller id=2] Ready to serve as the new controller with epoch 7 (kafka.controller.KafkaController) [2018-07-19 00:37:22,304] INFO [Controller id=2] Partitions undergoing preferred replica election: (kafka.controller.KafkaController) [2018-07-19 00:37:22,304] INFO [Controller id=2] Partitions that completed preferred replica election: (kafka.controller.KafkaController) [2018-07-19 00:37:22,304] INFO [Controller id=2] Skipping preferred replica election for partitions due to topic deletion: (kafka.controller.KafkaController) [2018-07-19 00:37:22,304] INFO [Controller id=2] Resuming preferred replica election for partitions: (kafka.controller.KafkaController) [2018-07-19 00:37:22,305] INFO [Controller id=2] Starting preferred replica leader election for partitions (kafka.controller.KafkaController) [2018-07-19 00:37:22,309] INFO [Controller id=2] Starting the controller scheduler (kafka.controller.KafkaController) [2018-07-19 00:37:27,311] TRACE [Controller id=2] Checking need to trigger auto leader balancing (kafka.controller.KafkaController) [2018-07-19 00:37:27,312] DEBUG [Controller id=2] Preferred replicas by broker Map() (kafka.controller.KafkaController) [2018-07-19 00:42:27,313] TRACE [Controller id=2] Checking need to trigger auto leader balancing (kafka.controller.KafkaController) [2018-07-19 00:42:27,313] DEBUG [Controller id=2] Preferred replicas by broker Map() (kafka.controller.KafkaController) [2018-07-19 00:47:27,313] TRACE [Controller id=2] Checking need to trigger auto leader balancing (kafka.controller.KafkaController) [2018-07-19 00:47:27,313] DEBUG [Controller id=2] Preferred replicas by broker Map() (kafka.controller.KafkaController) [2018-07-19 00:52:27,314] TRACE [Controller id=2] Checking need to trigger auto leader balancing (kafka.controller.KafkaController) [2018-07-19 00:52:27,314] DEBUG [Controller id=2] Preferred replicas by broker Map() (kafka.controller.KafkaController) [2018-07-19 00:57:27,314] TRACE [Controller id=2] Checking need to trigger auto leader balancing (kafka.controller.KafkaController) [2018-07-19 00:57:27,314] DEBUG [Controller id=2] Preferred replicas by broker Map() (kafka.controller.KafkaController) I dont see any error log. ... View more