Mazhar Shaikh created KAFKA-4128:
------------------------------------
Summary: Kafka broker loses messages when zookeeper session times
out
Key: KAFKA-4128
URL: https://issues.apache.org/jira/browse/KAFKA-4128
Project: Kafka
Issue Type: Bug
Affects Versions: 0.8.2.1
Reporter: Mazhar Shaikh
Pumping 30k msgs/second after some 6-8 hrs of run below logs are printed and
the messages are lost.
[More than 5k messages are lost on every partitions]
Below are few logs:
[2016-09-06 05:00:42,595] INFO Client session timed out, have not heard from
server in 20903ms for sessionid 0x256fabec47c0003, closing socket connection
and attempting reconnect (org.apache.zookeeper.ClientCnxn)
[2016-09-06 05:00:42,696] INFO zookeeper state changed (Disconnected)
(org.I0Itec.zkclient.ZkClient)
[2016-09-06 05:00:42,753] INFO Partition [topic,62] on broker 4: Shrinking ISR
for partition [topic,62] from 4,2 to 4 (kafka.cluster.Partition)
[2016-09-06 05:00:43,585] INFO Opening socket connection to server
sysctrl/169.254.2.1:2182. Will not attempt to authenticate using SASL (unknown
error) (org.apache.zookeeper.ClientCnxn)
[2016-09-06 05:00:43,586] INFO Socket connection established to
sysctrl/169.254.2.1:2182, initiating session (org.apache.zookeeper.ClientCnxn)
[2016-09-06 05:00:43,587] INFO Unable to read additional data from server
sessionid 0x256fabec47c0003, likely server has closed socket, closing socket
connection and attempting reconnect (org.apache.zookeeper.ClientCnxn)
[2016-09-06 05:00:44,644] INFO Opening socket connection to server
b1/169.254.2.116:2181. Will not attempt to authenticate using SASL (unknown
error) (org.apache.zookeeper.ClientCnxn)
[2016-09-06 05:00:44,651] INFO Socket connection established to
b1/169.254.2.116:2181, initiating session (org.apache.zookeeper.ClientCnxn)
[2016-09-06 05:00:44,658] INFO zookeeper state changed (Expired)
(org.I0Itec.zkclient.ZkClient)
[2016-09-06 05:00:44,659] INFO Initiating client connection,
connectString=b2.broker.com:2181,b1.broker.com:2181,zoo3.broker.com:2182
sessionTimeout=15000 watcher=org.I0Itec.zkclient.ZkClient@37b8e86a
(org.apache.zookeeper.ZooKeeper)
[2016-09-06 05:00:44,659] INFO Unable to reconnect to ZooKeeper service,
session 0x256fabec47c0003 has expired, closing socket connection
(org.apache.zookeeper.ClientCnxn)
[2016-09-06 05:00:44,661] INFO EventThread shut down
(org.apache.zookeeper.ClientCnxn)
[2016-09-06 05:00:44,662] INFO Opening socket connection to server
b2/169.254.2.216:2181. Will not attempt to authenticate using SASL (unknown
error) (org.apache.zookeeper.ClientCnxn)
[2016-09-06 05:00:44,662] INFO Socket connection established to
b2/169.254.2.216:2181, initiating session (org.apache.zookeeper.ClientCnxn)
[2016-09-06 05:00:44,665] ERROR Error handling event ZkEvent[New session event
sent to kafka.controller.KafkaController$SessionExpirationListener@33b7dedc]
(org.I0Itec.zkclient.ZkEventThread)
java.lang.IllegalStateException: Kafka scheduler has not been started
at kafka.utils.KafkaScheduler.ensureStarted(KafkaScheduler.scala:114)
at kafka.utils.KafkaScheduler.shutdown(KafkaScheduler.scala:86)
at
kafka.controller.KafkaController.onControllerResignation(KafkaController.scala:350)
at
kafka.controller.KafkaController$SessionExpirationListener$$anonfun$handleNewSession$1.apply$mcZ$sp(KafkaController.scala:1108)
at
kafka.controller.KafkaController$SessionExpirationListener$$anonfun$handleNewSession$1.apply(KafkaController.scala:1107)
at
kafka.controller.KafkaController$SessionExpirationListener$$anonfun$handleNewSession$1.apply(KafkaController.scala:1107)
at kafka.utils.Utils$.inLock(Utils.scala:535)
at
kafka.controller.KafkaController$SessionExpirationListener.handleNewSession(KafkaController.scala:1107)
at org.I0Itec.zkclient.ZkClient$4.run(ZkClient.java:472)
at org.I0Itec.zkclient.ZkEventThread.run(ZkEventThread.java:71)
[2016-09-06 05:00:44,666] INFO re-registering broker info in ZK for broker 4
(kafka.server.KafkaHealthcheck)
[2016-09-06 05:00:44,801] INFO Session establishment complete on server
b2/169.254.2.216:2181, sessionid = 0x256fabec47c0005, negotiated timeout =
15000 (org.apache.zookeeper.ClientCnxn)
[2016-09-06 05:00:44,802] INFO zookeeper state changed (SyncConnected)
(org.I0Itec.zkclient.ZkClient)
[2016-09-06 05:00:44,812] INFO Registered broker 4 at path /brokers/ids/4 with
address b5.broker.com:9092. (kafka.utils.ZkUtils$)
[2016-09-06 05:00:44,813] INFO done re-registering broker
(kafka.server.KafkaHealthcheck)
[2016-09-06 05:00:44,814] INFO Subscribing to /brokers/topics path to watch for
new topics (kafka.server.KafkaHealthcheck)
[2016-09-06 05:00:44,831] INFO Partition [topic,62] on broker 4: Expanding ISR
for partition [topic,62] from 4 to 4,2 (kafka.cluster.Partition)
[2016-09-06 05:00:44,865] INFO New leader is 1
(kafka.server.ZookeeperLeaderElector$LeaderChangeListener)
[2016-09-06 05:00:45,762] INFO [ReplicaFetcherManager on broker 4] Removed
fetcher for partitions
[topic,63],[topic,62],[topic,58],[topic,52],[topic,56],[topic,49],[topic,60],[topic,54],[topic,48],[topic,61],[topic,50],[topic,53],[topic,59],[topic,57],[topic,51],[topic,55]
(kafka.server.ReplicaFetcherManager)
[2016-09-06 05:00:45,764] INFO Truncating log topic-63 to offset 9971093.
(kafka.log.Log)
[2016-09-06 05:00:45,771] INFO Truncating log topic-62 to offset 9971439.
(kafka.log.Log)
[2016-09-06 05:00:45,773] INFO Truncating log topic-58 to offset 9971298.
(kafka.log.Log)
[2016-09-06 05:00:45,774] INFO Truncating log topic-52 to offset 9740617.
(kafka.log.Log)
[2016-09-06 05:00:45,775] INFO Truncating log topic-56 to offset 9971829.
(kafka.log.Log)
[2016-09-06 05:00:45,777] INFO Truncating log topic-49 to offset 9740178.
(kafka.log.Log)
[2016-09-06 05:00:45,778] INFO Truncating log topic-60 to offset 9971167.
(kafka.log.Log)
[2016-09-06 05:00:45,780] INFO Truncating log topic-54 to offset 9738892.
(kafka.log.Log)
[2016-09-06 05:00:45,781] INFO Truncating log topic-48 to offset 9739499.
(kafka.log.Log)
[2016-09-06 05:00:45,787] INFO Truncating log topic-61 to offset 9972030.
(kafka.log.Log)
[2016-09-06 05:00:45,788] INFO Truncating log topic-50 to offset 9740175.
(kafka.log.Log)
[2016-09-06 05:00:45,793] INFO Truncating log topic-53 to offset 9740074.
(kafka.log.Log)
[2016-09-06 05:00:45,794] INFO Truncating log topic-59 to offset 9971052.
(kafka.log.Log)
[2016-09-06 05:00:45,795] INFO Truncating log topic-57 to offset 9970962.
(kafka.log.Log)
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
