**** 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:2181sessionTim
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
>
