[2014-03-25 12:21:58,848] INFO Client session timed out, have not heard from server in 4001ms f or sessionid 0x54441e4dae0350a, closing socket connection and attempting reconnect (org.apache.zookeeper. ClientCnxn)
This is a problem. It indicates a GC pause or something similar on either the Kafka broker or your zookeeper server. That is the reason it keeps establishing new connections to zookeeper. You can enable gc logging or monitoring to confirm if that is the issue. Thanks, Neha On Thu, Mar 27, 2014 at 3:07 PM, Tom Amon <ta46...@gmail.com> wrote: > **** From the controller log **** > > > [2014-03-25 12:22:39,487] INFO [ControllerEpochListener on 2]: Initialized > controller epoch to > > 11 and zk version 10 (kafka.controller.ControllerEpochListener) > > [2014-03-25 12:22:39,519] INFO [Controller 2]: Controller starting up > (kafka.controller.KafkaCo > > ntroller) > > [2014-03-25 12:22:39,777] INFO [Controller 2]: Controller startup complete > (kafka.controller.Ka > > fkaController) > > [2014-03-25 19:47:59,198] INFO [ControllerEpochListener on 2]: Initialized > controller epoch to > > 11 and zk version 10 (kafka.controller.ControllerEpochListener) > > [2014-03-25 19:47:59,230] INFO [Controller 2]: Controller starting up > (kafka.controller.KafkaCo > > ntroller) > > [2014-03-25 19:47:59,379] INFO [Controller 2]: Controller startup complete > (kafka.controller.Ka > > fkaController) > > [2014-03-25 21:39:50,115] INFO [ControllerEpochListener on 2]: Initialized > controller epoch to > > 12 and zk version 11 (kafka.controller.ControllerEpochListener) > > [2014-03-25 21:59:18,020] INFO [Controller 2]: Broker 2 starting become > controller state transi > > tion (kafka.controller.KafkaController) > > [2014-03-25 21:59:18,032] INFO [Controller 2]: Controller 2 incremented > epoch to 13 (kafka.controller.KafkaController) > > [2014-03-25 21:59:21,888] INFO [Controller-2-to-broker-2-send-thread], > Starting (kafka.controller.RequestSendThread) > > [2014-03-25 21:59:21,895] INFO [Controller-2-to-broker-3-send-thread], > Starting (kafka.controller.RequestSendThread) > > [2014-03-25 21:59:21,895] INFO [Controller-2-to-broker-4-send-thread], > Starting (kafka.controller.RequestSendThread) > > [2014-03-25 21:59:21,895] INFO [Controller-2-to-broker-5-send-thread], > Starting (kafka.controller.RequestSendThread) > > [2014-03-25 21:59:21,898] INFO [Controller 2]: Currently active brokers in > the cluster: Set(2,3, 4, 5) (kafka.controller.KafkaController) > > [2014-03-25 21:59:21,899] INFO [Controller 2]: Currently shutting brokers > in the cluster: Set() (kafka.controller.KafkaController) > > [2014-03-25 21:59:21,899] INFO [Controller 2]: Current list of topics in > the cluster: Set(optimizer-error-topic, optimizer-default-topic, > metrics-tracker-audit) (kafka.controller.KafkaController) > > **** From the root log **** > > [2014-03-25 12:21:58,848] INFO Client session timed out, have not heard > from server in 4001ms f > or sessionid 0x54441e4dae0350a, closing socket connection and attempting > reconnect (org.apache.zookeeper.ClientCnxn) > [2014-03-25 12:21:58,948] INFO zookeeper state changed (Disconnected) > (org.I0Itec.zkclient.ZkClient) > [2014-03-25 12:21:59,136] INFO Opening socket connection to server > > slc5b01c-e48f.stratus.slc.com/10.120.104.37:2181(org.apache.zookeeper.ClientCnxn) > [2014-03-25 12:21:59,136] ERROR Unable to open socket to > slc5b01c-e48f.stratus.slc.com/10. > 120.104.37:2181 (org.apache.zookeeper.ClientCnxn) > [2014-03-25 12:21:59,137] WARN Session 0x54441e4dae0350a for server null, > unexpected error, closing socket connection and attempting reconnect > (org.apache.zookeeper.ClientCnxn) > java.net.SocketException: Network is unreachable > at sun.nio.ch.Net.connect(Native Method) > at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:525) > at > > org.apache.zookeeper.ClientCnxn$SendThread.startConnect(ClientCnxn.java:1068) > at > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1101) > [2014-03-25 12:21:59,450] INFO Opening socket connection to server > > slc5b01c-ef64.stratus.slc.com/10.120.108.36:2181(org.apache.zookeeper.ClientCnxn) > [2014-03-25 12:21:59,450] ERROR Unable to open socket to > slc5b01c-ef64.stratus.slc.com/10. > 120.108.36:2181 (org.apache.zookeeper.ClientCnxn) > [2014-03-25 12:21:59,450] WARN Session 0x54441e4dae0350a for server null, > unexpected error, closing socket connection and attempting reconnect > (org.apache.zookeeper.ClientCnxn) > java.net.SocketException: Network is unreachable > at sun.nio.ch.Net.connect(Native Method) > at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:525) > at > > org.apache.zookeeper.ClientCnxn$SendThread.startConnect(ClientCnxn.java:1068) > at > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1101) > [2014-03-25 12:21:59,827] INFO Opening socket connection to server > > slc5b01c-4593.stratus.slc.com/10.120.132.36:2181(org.apache.zookeeper.ClientCnxn) > [2014-03-25 12:21:59,828] ERROR Unable to open socket to > slc5b01c-4593.stratus.slc.com/10. > 120.132.36:2181 (org.apache.zookeeper.ClientCnxn) > [2014-03-25 12:21:59,828] WARN Session 0x54441e4dae0350a for server null, > unexpected error, closing socket connection and attempting reconnect > (org.apache.zookeeper.ClientCnxn) > java.net.SocketException: Network is unreachable > at sun.nio.ch.Net.connect(Native Method) > at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:525) > at > > org.apache.zookeeper.ClientCnxn$SendThread.startConnect(ClientCnxn.java:1068) > at > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1101) > [2014-03-25 12:22:38,950] INFO Starting ZkClient event thread. > (org.I0Itec.zkclient.ZkEventThre > ad) > [2014-03-25 12:22:39,071] INFO Client > environment:zookeeper.version=3.3.6-1366786, built on 07/29/2012 06:22 GMT > (org.apache.zookeeper.ZooKeeper) > [2014-03-25 12:22:39,071] INFO Client environment:host.name= > slc5b01c-7285.stratus.slc.com > (org.apache.zookeeper.ZooKeeper) > [2014-03-25 12:22:39,071] INFO Client environment:java.version=1.6.0_20 > (org.apache.zookeeper.ZooKeeper) > [2014-03-25 12:22:39,071] INFO Client environment:java.vendor=Sun > Microsystems Inc. (org.apache.zookeeper.ZooKeeper) > [2014-03-25 12:22:39,071] INFO Client > environment:java.home=/usr/lib/jvm/java-1.6.0-openjdk-1.6 > .0.0.x86_64/jre (org.apache.zookeeper.ZooKeeper) > [2014-03-25 12:22:39,071] INFO Client > environment:java.class.path=:/usr/local/kafka-0.8/bin/../ > > core/target/scala-2.8.0/*.jar:/usr/local/kafka-0.8/bin/../perf/target/scala-2.8.0/kafka*.jar:/u > > sr/local/kafka-0.8/bin/../libs/jopt-simple-3.2.jar:/usr/local/kafka-0.8/bin/../libs/log4j-1.2.1 > > 5.jar:/usr/local/kafka-0.8/bin/../libs/metrics-annotation-2.2.0.jar:/usr/local/kafka-0.8/bin/.. > > /libs/metrics-core-2.2.0.jar:/usr/local/kafka-0.8/bin/../libs/scala-compiler.jar:/usr/local/kaf > > ka-0.8/bin/../libs/scala-library.jar:/usr/local/kafka-0.8/bin/../libs/slf4j-api-1.7.2.jar:/usr/ > > local/kafka-0.8/bin/../libs/slf4j-simple-1.6.4.jar:/usr/local/kafka-0.8/bin/../libs/snappy-java > > -1.0.4.1.jar:/usr/local/kafka-0.8/bin/../libs/zkclient-0.3.jar:/usr/local/kafka-0.8/bin/../libs > /zookeeper-3.3.6.jar:/usr/local/kafka-0.8/bin/../kafka_2.8.0-0.8.0.jar > (org.apache.zookeeper.Zo > oKeeper) > [2014-03-25 12:22:39,072] INFO Client > environment:java.library.path=/usr/lib/jvm/java-1.6.0-ope > > njdk-1.6.0.0.x86_64/jre/lib/amd64/server:/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib > > /amd64:/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/../lib/amd64:/usr/java/packages/lib/a > md64:/usr/lib64:/lib64:/lib:/usr/lib (org.apache.zookeeper.ZooKeeper) > [2014-03-25 12:22:39,072] INFO Client environment:java.io.tmpdir=/tmp > (org.apache.zookeeper.ZooKeeper) > [2014-03-25 12:22:39,072] INFO Client environment:java.compiler=<NA> > (org.apache.zookeeper.ZooKeeper) > [2014-03-25 12:22:39,072] INFO Client environment:os.name=Linux > (org.apache.zookeeper.ZooKeeper) > [2014-03-25 12:22:39,072] INFO Client environment:os.arch=amd64 > (org.apache.zookeeper.ZooKeeper) > [2014-03-25 12:22:39,072] INFO Client > environment:os.version=2.6.32-131.0.15.el6.x86_64 > (org.apache.zookeeper.ZooKeeper) > [2014-03-25 12:22:39,072] INFO Client environment:user.name=root > (org.apache.zookeeper.ZooKeeper) > [2014-03-25 12:22:39,072] INFO Client environment:user.home=/root > (org.apache.zookeeper.ZooKeeper) > [2014-03-25 12:22:39,072] INFO Client environment:user.dir=/ > (org.apache.zookeeper.ZooKeeper) > [2014-03-25 12:22:39,072] INFO Initiating client connection, > connectString=slc5b01c-e48f.stratu > s.slc.com:2181,slc5b01c-ef64.stratus.slc.com:2181, > slc5b01c-f83e.stratus.slc.com: > 2181,slc5b01c-4593.stratus.slc.com:2181,slc5b01c-95d1.stratus.slc.com:2181 > sessionTim > eout=6000 watcher=org.I0Itec.zkclient.ZkClient@7e94af2f > (org.apache.zookeeper.ZooKeeper) > [2014-03-25 12:22:39,168] INFO Opening socket connection to server > > slc5b01c-e48f.stratus.slc.com/10.120.104.37:2181(org.apache.zookeeper.ClientCnxn) > [2014-03-25 12:22:39,188] INFO Socket connection established to > slc5b01c-e48f.stratus.slc. > com/10.120.104.37:2181, initiating session > (org.apache.zookeeper.ClientCnxn) > [2014-03-25 12:22:39,213] INFO Session establishment complete on server > slc5b01c-e48f.stratus.slc.com/10.120.104.37:2181, sessionid = > 0x144f6b7e58f009d, negotiated timeout = 6000 > (org.apache.zookeeper.ClientCnxn) > [2014-03-25 12:22:39,214] INFO zookeeper state changed (SyncConnected) > (org.I0Itec.zkclient.ZkClient) > > > > ------------------------------------------------------------------- > > Could you send around the corresponding broker log during the same > timeframe? There are several connection attempts to zookeeper. Are you sure > there are no consumers running at the same time? Also, how many brokers > were started in this timeframe? > > > > Thanks, > > Neha > > > > > > On Tue, Mar 25, 2014 at 12:55 PM, Tom Amon <ta46...@gmail.com> wrote: > > > > > Again thank you for your patience.... > > > > > > Is the following pattern normal for a broker that is booting? This is > > > from my zookeeper log. It seems to connect and disconnect multiple > > > times in rapid succession. The last message is a disconnect message > > > with no subsequent connect. Other zookeeper boxes don't show any > > > activity for this ip address. > > > > > > 2014-03-25 12:21:18,906 - INFO [NIOServerCxn.Factory: > > > 0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket > > > connection from /10.120.80.36:34417 > > > 2014-03-25 12:21:18,908 - INFO [NIOServerCxn.Factory: > > > 0.0.0.0/0.0.0.0:2181:NIOServerCnxn@777] - Client attempting to > > > establish new session at /10.120.80.36:34417 > > > 2014-03-25 12:21:18,924 - INFO [CommitProcessor:1:NIOServerCnxn@1580] > > > - Established session 0x144f6b7e58f009b with negotiated timeout 30000 > > > for client /10.120.80.36:34417 > > > 2014-03-25 12:21:24,958 - INFO [NIOServerCxn.Factory: > > > 0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection > > > for client /10.120.80.36:34417 which had sessionid 0x144f6b7e58f009b > > > 2014-03-25 12:21:28,229 - INFO [NIOServerCxn.Factory: > > > 0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket > > > connection from /10.120.80.36:34422 > > > 2014-03-25 12:21:28,231 - INFO [NIOServerCxn.Factory: > > > 0.0.0.0/0.0.0.0:2181:NIOServerCnxn@777] - Client attempting to > > > establish new session at /10.120.80.36:34422 > > > 2014-03-25 12:21:28,239 - INFO [CommitProcessor:1:NIOServerCnxn@1580] > > > - Established session 0x144f6b7e58f009c with negotiated timeout 30000 > > > for client /10.120.80.36:34422 > > > 2014-03-25 12:21:34,538 - INFO [NIOServerCxn.Factory: > > > 0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection > > > for client /10.120.80.36:34422 which had sessionid 0x144f6b7e58f009c > > > 2014-03-25 12:22:39,452 - INFO [NIOServerCxn.Factory: > > > 0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket > > > connection from /10.120.80.36:39296 > > > 2014-03-25 12:22:39,455 - INFO [NIOServerCxn.Factory: > > > 0.0.0.0/0.0.0.0:2181:NIOServerCnxn@777] - Client attempting to > > > establish new session at /10.120.80.36:39296 > > > 2014-03-25 12:22:39,476 - INFO [CommitProcessor:1:NIOServerCnxn@1580] > > > - Established session 0x144f6b7e58f009d with negotiated timeout 6000 > > > for client /10.120.80.36:39296 > > > 2014-03-25 12:24:58,851 - INFO [NIOServerCxn.Factory: > > > 0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket > > > connection from /10.120.80.36:39332 > > > 2014-03-25 12:24:58,854 - INFO [NIOServerCxn.Factory: > > > 0.0.0.0/0.0.0.0:2181:NIOServerCnxn@777] - Client attempting to > > > establish new session at /10.120.80.36:39332 > > > 2014-03-25 12:24:58,867 - INFO [CommitProcessor:1:NIOServerCnxn@1580] > > > - Established session 0x144f6b7e58f009e with negotiated timeout 30000 > > > for client /10.120.80.36:39332 > > > 2014-03-25 12:25:06,892 - INFO [NIOServerCxn.Factory: > > > 0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection > > > for client /10.120.80.36:39332 which had sessionid 0x144f6b7e58f009e > > > >
