You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@kafka.apache.org by Tony John <to...@gmail.com> on 2018/02/05 08:00:38 UTC
Kafka Streams : Connection to node -1 could not be established.
Broker may not be available.
Hi All,
I have been running a streams application for sometime. The application
runs fine for sometime but after a day or two I see the below log getting
printed continuously on to the console.
WARN 2018-02-05 02:50:04.060 [kafka-producer-network-thread | producer-1]
org.apache.kafka.clients.NetworkClient - Connection to node -1 could not be
established. Broker may not be available.
WARN 2018-02-05 02:50:04.160 [kafka-producer-network-thread | producer-1]
org.apache.kafka.clients.NetworkClient - Connection to node -1 could not be
established. Broker may not be available.
WARN 2018-02-05 02:50:04.261 [kafka-producer-network-thread | producer-1]
org.apache.kafka.clients.NetworkClient - Connection to node -1 could not be
established. Broker may not be available.
WARN 2018-02-05 02:50:04.311 [kafka-producer-network-thread | producer-1]
org.apache.kafka.clients.NetworkClient - Connection to node -1 could not be
established. Broker may not be available.
WARN 2018-02-05 02:50:04.361 [kafka-producer-network-thread | producer-1]
org.apache.kafka.clients.NetworkClient - Connection to node -1 could not be
established. Broker may not be available.
WARN 2018-02-05 02:50:04.411 [kafka-producer-network-thread | producer-1]
org.apache.kafka.clients.NetworkClient - Connection to node -1 could not be
established. Broker may not be available.
At this time, though the application is able to process the messages, I
could also see lag building up in the consumers and the processing time for
a batch has increased 15 folds.
I am using a single zoo-keeper instance with 2 brokers and 4 application
instances. I checked the broker and zoo-keeper status, they are all running
fine as I could see. I have also verified the connectivity between the
application and broker instances using telnet and it seems intact. The
kafka broker and streams/client versions are 0.11.0.2. Results of broker
status results from zoo-keeper below
[root@app100 kafka]# echo dump | nc localhost 2181
SessionTracker dump:
Session Sets (3):
0 expire at Mon Feb 05 06:16:39 UTC 2018:
1 expire at Mon Feb 05 06:16:42 UTC 2018:
0x161562860970001
1 expire at Mon Feb 05 06:16:45 UTC 2018:
0x161562860970000
ephemeral nodes dump:
Sessions with Ephemerals (2):
0x161562860970000:
/brokers/ids/0
/controller
0x161562860970001:
/brokers/ids/1
[root@app100 kafka]# ./kafka_2.11-0.11.0.2/bin/zookeeper-shell.sh
localhost:2181 <<< "get /brokers/ids/0"
Connecting to localhost:2181
Welcome to ZooKeeper!
JLine support is disabled
WATCHER::
WatchedEvent state:SyncConnected type:None path:null
{"listener_security_protocol_map":{"PLAINTEXT":"PLAINTEXT"}
,"endpoints":["PLAINTEXT://172.31.10.35:9092"],"jmx_port":
55555,"host":"172.31.10.35","timestamp":"1517569007467","
port":9092,"version":4}
cZxid = 0x1c
ctime = Fri Feb 02 10:56:47 UTC 2018
mZxid = 0x1c
mtime = Fri Feb 02 10:56:47 UTC 2018
pZxid = 0x1c
cversion = 0
dataVersion = 0
aclVersion = 0
ephemeralOwner = 0x161562860970000
dataLength = 197
numChildren = 0
[root@app100 kafka]# ./kafka_2.11-0.11.0.2/bin/zookeeper-shell.sh
localhost:2181 <<< "get /brokers/ids/1"
Connecting to localhost:2181
Welcome to ZooKeeper!
JLine support is disabled
WATCHER::
WatchedEvent state:SyncConnected type:None path:null
{"listener_security_protocol_map":{"PLAINTEXT":"PLAINTEXT"}
,"endpoints":["PLAINTEXT://172.31.14.8:9092"],"jmx_port":
55555,"host":"172.31.14.8","timestamp":"1517569016562","
port":9092,"version":4}
cZxid = 0x21
ctime = Fri Feb 02 10:56:56 UTC 2018
mZxid = 0x21
mtime = Fri Feb 02 10:56:56 UTC 2018
pZxid = 0x21
cversion = 0
dataVersion = 0
aclVersion = 0
ephemeralOwner = 0x161562860970001
dataLength = 195
numChildren = 0
Could you please throw some light on this as to what could be going wrong
here?
Thanks,
Tony
Re: Kafka Streams : Connection to node -1 could not be established.
Broker may not be available.
Posted by Tony John <to...@gmail.com>.
Thanks a lot Guozhang. I was able to nail it down by looking at the log
which you suggested. The log revealed that it was trying to connect to
localhost and it was a problem with one of my sub component. It was trying
to read the broker configuration from a different property file which
didn't exist and defaulted to loopback address.
Thanks a lot for the help.
Thanks,
Tony
On Wed, Feb 7, 2018 at 3:05 AM, Guozhang Wang <wa...@gmail.com> wrote:
> Hi Tony,
>
> Your Streams configs look good to me, and the additional streams log from
> StreamThread are normal operational logs that do not related to the issue.
> I suspect there is a network partition between your client to the broker
> node, and to investigate which host this `node -1` is referring to (note
> that -1 is actually a valid node id, read from the bootstrapped list), you
> can look into the same log file and search for the following line:
>
> "Initiating connection to node.."
>
> and the find out the host:port of node with id -1 .
>
> Guozhang
>
> On Tue, Feb 6, 2018 at 8:16 AM, Tony John <to...@gmail.com>
> wrote:
>
> > Hi Guozhang,
> >
> > Thanks for looking into this. Below are the stream config values.
> >
> > INFO 2018-02-02 08:33:25.708 [main] org.apache.kafka.streams.
> > StreamsConfig
> > - StreamsConfig values:
> > application.id = cv-v1
> > application.server =
> > bootstrap.servers = [172.31.10.35:9092, 172.31.14.8:9092]
> > buffered.records.per.partition = 1000
> > cache.max.bytes.buffering = 104857600
> > client.id = I2
> > commit.interval.ms = 30000
> > connections.max.idle.ms = 540000
> > default.key.serde = class
> > org.apache.kafka.common.serialization.Serdes$ByteArraySerde
> > default.timestamp.extractor = class
> > org.apache.kafka.streams.processor.FailOnInvalidTimestamp
> > default.value.serde = class
> > org.apache.kafka.common.serialization.Serdes$ByteArraySerde
> > key.serde = null
> > metadata.max.age.ms = 300000
> > metric.reporters = []
> > metrics.num.samples = 2
> > metrics.recording.level = DEBUG
> > metrics.sample.window.ms = 30000
> > num.standby.replicas = 1
> > num.stream.threads = 1
> > partition.grouper = class
> > org.apache.kafka.streams.processor.DefaultPartitionGrouper
> > poll.ms = 100
> > processing.guarantee = at_least_once
> > receive.buffer.bytes = 32768
> > reconnect.backoff.max.ms = 1000
> > reconnect.backoff.ms = 50
> > replication.factor = 2
> > request.timeout.ms = 40000
> > retry.backoff.ms = 100
> > rocksdb.config.setter = null
> > security.protocol = PLAINTEXT
> > send.buffer.bytes = 131072
> > state.cleanup.delay.ms = 600000
> > state.dir = /mnt/store/kafka-streams
> > timestamp.extractor = null
> > value.serde = null
> > windowstore.changelog.additional.retention.ms = 86400000
> > zookeeper.connect =
> > INFO 2018-02-02 08:33:25.870 [main] org.apache.kafka.streams.
> > StreamsConfig
> > - StreamsConfig values:
> > application.id = pe-v1
> > application.server =
> > bootstrap.servers = [172.31.10.35:9092, 172.31.14.8:9092]
> > buffered.records.per.partition = 1000
> > cache.max.bytes.buffering = 2147483648
> > client.id = I2
> > commit.interval.ms = 30000
> > connections.max.idle.ms = 540000
> > default.key.serde = class
> > org.apache.kafka.common.serialization.Serdes$ByteArraySerde
> > default.timestamp.extractor = class
> > org.apache.kafka.streams.processor.FailOnInvalidTimestamp
> > default.value.serde = class
> > org.apache.kafka.common.serialization.Serdes$ByteArraySerde
> > key.serde = null
> > metadata.max.age.ms = 300000
> > metric.reporters = []
> > metrics.num.samples = 2
> > metrics.recording.level = DEBUG
> > metrics.sample.window.ms = 30000
> > num.standby.replicas = 1
> > num.stream.threads = 3
> > partition.grouper = class
> > org.apache.kafka.streams.processor.DefaultPartitionGrouper
> > poll.ms = 100
> > processing.guarantee = at_least_once
> > receive.buffer.bytes = 32768
> > reconnect.backoff.max.ms = 1000
> > reconnect.backoff.ms = 50
> > replication.factor = 2
> > request.timeout.ms = 40000
> > retry.backoff.ms = 100
> > rocksdb.config.setter = null
> > security.protocol = PLAINTEXT
> > send.buffer.bytes = 131072
> > state.cleanup.delay.ms = 600000
> > state.dir = /mnt/store/kafka-streams
> > timestamp.extractor = null
> > value.serde = null
> > windowstore.changelog.additional.retention.ms = 86400000
> > zookeeper.connect =
> >
> > Please note there are 2 streams application running.
> >
> > Apart from the Broker connectivity issue, I see the below logs as well.
> > What does that indicate and does it have any impact on the processing?
> >
> > DEBUG 2018-02-05 11:06:07.369 [I2-StreamThread-5]
> > org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread
> > [I2-StreamThread-5] processing latency 6694 < commit time 30000 for 10000
> > records. Adjusting up recordsProcessedBeforeCommit=44816
> > DEBUG 2018-02-05 11:06:07.518 [I2-StreamThread-3]
> > org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread
> > [I2-StreamThread-3] processing latency 3684 < commit time 30000 for 10000
> > records. Adjusting up recordsProcessedBeforeCommit=81433
> > DEBUG 2018-02-05 11:06:07.562 [I2-StreamThread-4]
> > org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread
> > [I2-StreamThread-4] processing latency 3620 < commit time 30000 for 10000
> > records. Adjusting up recordsProcessedBeforeCommit=82872
> > DEBUG 2018-02-05 11:06:09.838 [I2-StreamThread-7]
> > org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread
> > [I2-StreamThread-7] processing latency 3843 < commit time 30000 for 10000
> > records. Adjusting up recordsProcessedBeforeCommit=78064
> > DEBUG 2018-02-05 11:06:10.073 [I2-StreamThread-3]
> > org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread
> > [I2-StreamThread-3] processing latency 2552 < commit time 30000 for 7193
> > records. Adjusting up recordsProcessedBeforeCommit=84557
> > DEBUG 2018-02-05 11:06:10.209 [I2-StreamThread-4]
> > org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread
> > [I2-StreamThread-4] processing latency 2645 < commit time 30000 for 7161
> > records. Adjusting up recordsProcessedBeforeCommit=81221
> > DEBUG 2018-02-05 11:06:11.940 [I2-StreamThread-5]
> > org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread
> > [I2-StreamThread-5] processing latency 4568 < commit time 30000 for 7583
> > records. Adjusting up recordsProcessedBeforeCommit=49800
> > DEBUG 2018-02-05 11:06:12.538 [I2-StreamThread-7]
> > org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread
> > [I2-StreamThread-7] processing latency 2698 < commit time 30000 for 6880
> > records. Adjusting up recordsProcessedBeforeCommit=76501
> >
> >
> > Thanks,
> > Tony
> >
> > On Tue, Feb 6, 2018 at 3:21 AM, Guozhang Wang <wa...@gmail.com>
> wrote:
> >
> > > Hello Tony,
> > >
> > >
> > > Could you share your Streams config values so that people can help
> > further
> > > investigating your issue?
> > >
> > >
> > > Guozhang
> > >
> > >
> > > On Mon, Feb 5, 2018 at 12:00 AM, Tony John <to...@gmail.com>
> > > wrote:
> > >
> > > > Hi All,
> > > >
> > > > I have been running a streams application for sometime. The
> application
> > > > runs fine for sometime but after a day or two I see the below log
> > getting
> > > > printed continuously on to the console.
> > > >
> > > > WARN 2018-02-05 02:50:04.060 [kafka-producer-network-thread |
> > > producer-1]
> > > > org.apache.kafka.clients.NetworkClient - Connection to node -1 could
> > not
> > > > be
> > > > established. Broker may not be available.
> > > >
> > > > WARN 2018-02-05 02:50:04.160 [kafka-producer-network-thread |
> > > producer-1]
> > > > org.apache.kafka.clients.NetworkClient - Connection to node -1 could
> > not
> > > > be
> > > > established. Broker may not be available.
> > > >
> > > > WARN 2018-02-05 02:50:04.261 [kafka-producer-network-thread |
> > > producer-1]
> > > > org.apache.kafka.clients.NetworkClient - Connection to node -1 could
> > not
> > > > be
> > > > established. Broker may not be available.
> > > >
> > > > WARN 2018-02-05 02:50:04.311 [kafka-producer-network-thread |
> > > producer-1]
> > > > org.apache.kafka.clients.NetworkClient - Connection to node -1 could
> > not
> > > > be
> > > > established. Broker may not be available.
> > > >
> > > > WARN 2018-02-05 02:50:04.361 [kafka-producer-network-thread |
> > > producer-1]
> > > > org.apache.kafka.clients.NetworkClient - Connection to node -1 could
> > not
> > > > be
> > > > established. Broker may not be available.
> > > >
> > > > WARN 2018-02-05 02:50:04.411 [kafka-producer-network-thread |
> > > producer-1]
> > > > org.apache.kafka.clients.NetworkClient - Connection to node -1 could
> > not
> > > > be
> > > > established. Broker may not be available.
> > > >
> > > > At this time, though the application is able to process the
> messages, I
> > > > could also see lag building up in the consumers and the processing
> time
> > > for
> > > > a batch has increased 15 folds.
> > > >
> > > > I am using a single zoo-keeper instance with 2 brokers and 4
> > application
> > > > instances. I checked the broker and zoo-keeper status, they are all
> > > running
> > > > fine as I could see. I have also verified the connectivity between
> the
> > > > application and broker instances using telnet and it seems intact.
> The
> > > > kafka broker and streams/client versions are 0.11.0.2. Results of
> > broker
> > > > status results from zoo-keeper below
> > > >
> > > >
> > > > [root@app100 kafka]# echo dump | nc localhost 2181
> > > >
> > > > SessionTracker dump:
> > > >
> > > > Session Sets (3):
> > > >
> > > > 0 expire at Mon Feb 05 06:16:39 UTC 2018:
> > > >
> > > > 1 expire at Mon Feb 05 06:16:42 UTC 2018:
> > > >
> > > > 0x161562860970001
> > > >
> > > > 1 expire at Mon Feb 05 06:16:45 UTC 2018:
> > > >
> > > > 0x161562860970000
> > > >
> > > > ephemeral nodes dump:
> > > >
> > > > Sessions with Ephemerals (2):
> > > >
> > > > 0x161562860970000:
> > > >
> > > > /brokers/ids/0
> > > >
> > > > /controller
> > > >
> > > > 0x161562860970001:
> > > >
> > > > /brokers/ids/1
> > > >
> > > > [root@app100 kafka]# ./kafka_2.11-0.11.0.2/bin/zookeeper-shell.sh
> > > > localhost:2181 <<< "get /brokers/ids/0"
> > > >
> > > > Connecting to localhost:2181
> > > >
> > > > Welcome to ZooKeeper!
> > > >
> > > > JLine support is disabled
> > > >
> > > >
> > > > WATCHER::
> > > >
> > > >
> > > > WatchedEvent state:SyncConnected type:None path:null
> > > >
> > > > {"listener_security_protocol_map":{"PLAINTEXT":"PLAINTEXT"}
> > > > ,"endpoints":["PLAINTEXT://172.31.10.35:9092"],"jmx_port":
> > > > 55555,"host":"172.31.10.35","timestamp":"1517569007467","
> > > > port":9092,"version":4}
> > > >
> > > > cZxid = 0x1c
> > > >
> > > > ctime = Fri Feb 02 10:56:47 UTC 2018
> > > >
> > > > mZxid = 0x1c
> > > >
> > > > mtime = Fri Feb 02 10:56:47 UTC 2018
> > > >
> > > > pZxid = 0x1c
> > > >
> > > > cversion = 0
> > > >
> > > > dataVersion = 0
> > > >
> > > > aclVersion = 0
> > > >
> > > > ephemeralOwner = 0x161562860970000
> > > >
> > > > dataLength = 197
> > > >
> > > > numChildren = 0
> > > >
> > > > [root@app100 kafka]# ./kafka_2.11-0.11.0.2/bin/zookeeper-shell.sh
> > > > localhost:2181 <<< "get /brokers/ids/1"
> > > >
> > > > Connecting to localhost:2181
> > > >
> > > > Welcome to ZooKeeper!
> > > >
> > > > JLine support is disabled
> > > >
> > > >
> > > > WATCHER::
> > > >
> > > >
> > > > WatchedEvent state:SyncConnected type:None path:null
> > > >
> > > > {"listener_security_protocol_map":{"PLAINTEXT":"PLAINTEXT"}
> > > > ,"endpoints":["PLAINTEXT://172.31.14.8:9092"],"jmx_port":
> > > > 55555,"host":"172.31.14.8","timestamp":"1517569016562","
> > > > port":9092,"version":4}
> > > >
> > > > cZxid = 0x21
> > > >
> > > > ctime = Fri Feb 02 10:56:56 UTC 2018
> > > >
> > > > mZxid = 0x21
> > > >
> > > > mtime = Fri Feb 02 10:56:56 UTC 2018
> > > >
> > > > pZxid = 0x21
> > > >
> > > > cversion = 0
> > > >
> > > > dataVersion = 0
> > > >
> > > > aclVersion = 0
> > > >
> > > > ephemeralOwner = 0x161562860970001
> > > >
> > > > dataLength = 195
> > > >
> > > > numChildren = 0
> > > >
> > > > Could you please throw some light on this as to what could be going
> > wrong
> > > > here?
> > > >
> > > > Thanks,
> > > > Tony
> > > >
> > >
> > >
> > >
> > > --
> > > -- Guozhang
> > >
> >
>
>
>
> --
> -- Guozhang
>
Re: Kafka Streams : Connection to node -1 could not be established.
Broker may not be available.
Posted by Guozhang Wang <wa...@gmail.com>.
Hi Tony,
Your Streams configs look good to me, and the additional streams log from
StreamThread are normal operational logs that do not related to the issue.
I suspect there is a network partition between your client to the broker
node, and to investigate which host this `node -1` is referring to (note
that -1 is actually a valid node id, read from the bootstrapped list), you
can look into the same log file and search for the following line:
"Initiating connection to node.."
and the find out the host:port of node with id -1 .
Guozhang
On Tue, Feb 6, 2018 at 8:16 AM, Tony John <to...@gmail.com> wrote:
> Hi Guozhang,
>
> Thanks for looking into this. Below are the stream config values.
>
> INFO 2018-02-02 08:33:25.708 [main] org.apache.kafka.streams.
> StreamsConfig
> - StreamsConfig values:
> application.id = cv-v1
> application.server =
> bootstrap.servers = [172.31.10.35:9092, 172.31.14.8:9092]
> buffered.records.per.partition = 1000
> cache.max.bytes.buffering = 104857600
> client.id = I2
> commit.interval.ms = 30000
> connections.max.idle.ms = 540000
> default.key.serde = class
> org.apache.kafka.common.serialization.Serdes$ByteArraySerde
> default.timestamp.extractor = class
> org.apache.kafka.streams.processor.FailOnInvalidTimestamp
> default.value.serde = class
> org.apache.kafka.common.serialization.Serdes$ByteArraySerde
> key.serde = null
> metadata.max.age.ms = 300000
> metric.reporters = []
> metrics.num.samples = 2
> metrics.recording.level = DEBUG
> metrics.sample.window.ms = 30000
> num.standby.replicas = 1
> num.stream.threads = 1
> partition.grouper = class
> org.apache.kafka.streams.processor.DefaultPartitionGrouper
> poll.ms = 100
> processing.guarantee = at_least_once
> receive.buffer.bytes = 32768
> reconnect.backoff.max.ms = 1000
> reconnect.backoff.ms = 50
> replication.factor = 2
> request.timeout.ms = 40000
> retry.backoff.ms = 100
> rocksdb.config.setter = null
> security.protocol = PLAINTEXT
> send.buffer.bytes = 131072
> state.cleanup.delay.ms = 600000
> state.dir = /mnt/store/kafka-streams
> timestamp.extractor = null
> value.serde = null
> windowstore.changelog.additional.retention.ms = 86400000
> zookeeper.connect =
> INFO 2018-02-02 08:33:25.870 [main] org.apache.kafka.streams.
> StreamsConfig
> - StreamsConfig values:
> application.id = pe-v1
> application.server =
> bootstrap.servers = [172.31.10.35:9092, 172.31.14.8:9092]
> buffered.records.per.partition = 1000
> cache.max.bytes.buffering = 2147483648
> client.id = I2
> commit.interval.ms = 30000
> connections.max.idle.ms = 540000
> default.key.serde = class
> org.apache.kafka.common.serialization.Serdes$ByteArraySerde
> default.timestamp.extractor = class
> org.apache.kafka.streams.processor.FailOnInvalidTimestamp
> default.value.serde = class
> org.apache.kafka.common.serialization.Serdes$ByteArraySerde
> key.serde = null
> metadata.max.age.ms = 300000
> metric.reporters = []
> metrics.num.samples = 2
> metrics.recording.level = DEBUG
> metrics.sample.window.ms = 30000
> num.standby.replicas = 1
> num.stream.threads = 3
> partition.grouper = class
> org.apache.kafka.streams.processor.DefaultPartitionGrouper
> poll.ms = 100
> processing.guarantee = at_least_once
> receive.buffer.bytes = 32768
> reconnect.backoff.max.ms = 1000
> reconnect.backoff.ms = 50
> replication.factor = 2
> request.timeout.ms = 40000
> retry.backoff.ms = 100
> rocksdb.config.setter = null
> security.protocol = PLAINTEXT
> send.buffer.bytes = 131072
> state.cleanup.delay.ms = 600000
> state.dir = /mnt/store/kafka-streams
> timestamp.extractor = null
> value.serde = null
> windowstore.changelog.additional.retention.ms = 86400000
> zookeeper.connect =
>
> Please note there are 2 streams application running.
>
> Apart from the Broker connectivity issue, I see the below logs as well.
> What does that indicate and does it have any impact on the processing?
>
> DEBUG 2018-02-05 11:06:07.369 [I2-StreamThread-5]
> org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
> [I2-StreamThread-5] processing latency 6694 < commit time 30000 for 10000
> records. Adjusting up recordsProcessedBeforeCommit=44816
> DEBUG 2018-02-05 11:06:07.518 [I2-StreamThread-3]
> org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
> [I2-StreamThread-3] processing latency 3684 < commit time 30000 for 10000
> records. Adjusting up recordsProcessedBeforeCommit=81433
> DEBUG 2018-02-05 11:06:07.562 [I2-StreamThread-4]
> org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
> [I2-StreamThread-4] processing latency 3620 < commit time 30000 for 10000
> records. Adjusting up recordsProcessedBeforeCommit=82872
> DEBUG 2018-02-05 11:06:09.838 [I2-StreamThread-7]
> org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
> [I2-StreamThread-7] processing latency 3843 < commit time 30000 for 10000
> records. Adjusting up recordsProcessedBeforeCommit=78064
> DEBUG 2018-02-05 11:06:10.073 [I2-StreamThread-3]
> org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
> [I2-StreamThread-3] processing latency 2552 < commit time 30000 for 7193
> records. Adjusting up recordsProcessedBeforeCommit=84557
> DEBUG 2018-02-05 11:06:10.209 [I2-StreamThread-4]
> org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
> [I2-StreamThread-4] processing latency 2645 < commit time 30000 for 7161
> records. Adjusting up recordsProcessedBeforeCommit=81221
> DEBUG 2018-02-05 11:06:11.940 [I2-StreamThread-5]
> org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
> [I2-StreamThread-5] processing latency 4568 < commit time 30000 for 7583
> records. Adjusting up recordsProcessedBeforeCommit=49800
> DEBUG 2018-02-05 11:06:12.538 [I2-StreamThread-7]
> org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
> [I2-StreamThread-7] processing latency 2698 < commit time 30000 for 6880
> records. Adjusting up recordsProcessedBeforeCommit=76501
>
>
> Thanks,
> Tony
>
> On Tue, Feb 6, 2018 at 3:21 AM, Guozhang Wang <wa...@gmail.com> wrote:
>
> > Hello Tony,
> >
> >
> > Could you share your Streams config values so that people can help
> further
> > investigating your issue?
> >
> >
> > Guozhang
> >
> >
> > On Mon, Feb 5, 2018 at 12:00 AM, Tony John <to...@gmail.com>
> > wrote:
> >
> > > Hi All,
> > >
> > > I have been running a streams application for sometime. The application
> > > runs fine for sometime but after a day or two I see the below log
> getting
> > > printed continuously on to the console.
> > >
> > > WARN 2018-02-05 02:50:04.060 [kafka-producer-network-thread |
> > producer-1]
> > > org.apache.kafka.clients.NetworkClient - Connection to node -1 could
> not
> > > be
> > > established. Broker may not be available.
> > >
> > > WARN 2018-02-05 02:50:04.160 [kafka-producer-network-thread |
> > producer-1]
> > > org.apache.kafka.clients.NetworkClient - Connection to node -1 could
> not
> > > be
> > > established. Broker may not be available.
> > >
> > > WARN 2018-02-05 02:50:04.261 [kafka-producer-network-thread |
> > producer-1]
> > > org.apache.kafka.clients.NetworkClient - Connection to node -1 could
> not
> > > be
> > > established. Broker may not be available.
> > >
> > > WARN 2018-02-05 02:50:04.311 [kafka-producer-network-thread |
> > producer-1]
> > > org.apache.kafka.clients.NetworkClient - Connection to node -1 could
> not
> > > be
> > > established. Broker may not be available.
> > >
> > > WARN 2018-02-05 02:50:04.361 [kafka-producer-network-thread |
> > producer-1]
> > > org.apache.kafka.clients.NetworkClient - Connection to node -1 could
> not
> > > be
> > > established. Broker may not be available.
> > >
> > > WARN 2018-02-05 02:50:04.411 [kafka-producer-network-thread |
> > producer-1]
> > > org.apache.kafka.clients.NetworkClient - Connection to node -1 could
> not
> > > be
> > > established. Broker may not be available.
> > >
> > > At this time, though the application is able to process the messages, I
> > > could also see lag building up in the consumers and the processing time
> > for
> > > a batch has increased 15 folds.
> > >
> > > I am using a single zoo-keeper instance with 2 brokers and 4
> application
> > > instances. I checked the broker and zoo-keeper status, they are all
> > running
> > > fine as I could see. I have also verified the connectivity between the
> > > application and broker instances using telnet and it seems intact. The
> > > kafka broker and streams/client versions are 0.11.0.2. Results of
> broker
> > > status results from zoo-keeper below
> > >
> > >
> > > [root@app100 kafka]# echo dump | nc localhost 2181
> > >
> > > SessionTracker dump:
> > >
> > > Session Sets (3):
> > >
> > > 0 expire at Mon Feb 05 06:16:39 UTC 2018:
> > >
> > > 1 expire at Mon Feb 05 06:16:42 UTC 2018:
> > >
> > > 0x161562860970001
> > >
> > > 1 expire at Mon Feb 05 06:16:45 UTC 2018:
> > >
> > > 0x161562860970000
> > >
> > > ephemeral nodes dump:
> > >
> > > Sessions with Ephemerals (2):
> > >
> > > 0x161562860970000:
> > >
> > > /brokers/ids/0
> > >
> > > /controller
> > >
> > > 0x161562860970001:
> > >
> > > /brokers/ids/1
> > >
> > > [root@app100 kafka]# ./kafka_2.11-0.11.0.2/bin/zookeeper-shell.sh
> > > localhost:2181 <<< "get /brokers/ids/0"
> > >
> > > Connecting to localhost:2181
> > >
> > > Welcome to ZooKeeper!
> > >
> > > JLine support is disabled
> > >
> > >
> > > WATCHER::
> > >
> > >
> > > WatchedEvent state:SyncConnected type:None path:null
> > >
> > > {"listener_security_protocol_map":{"PLAINTEXT":"PLAINTEXT"}
> > > ,"endpoints":["PLAINTEXT://172.31.10.35:9092"],"jmx_port":
> > > 55555,"host":"172.31.10.35","timestamp":"1517569007467","
> > > port":9092,"version":4}
> > >
> > > cZxid = 0x1c
> > >
> > > ctime = Fri Feb 02 10:56:47 UTC 2018
> > >
> > > mZxid = 0x1c
> > >
> > > mtime = Fri Feb 02 10:56:47 UTC 2018
> > >
> > > pZxid = 0x1c
> > >
> > > cversion = 0
> > >
> > > dataVersion = 0
> > >
> > > aclVersion = 0
> > >
> > > ephemeralOwner = 0x161562860970000
> > >
> > > dataLength = 197
> > >
> > > numChildren = 0
> > >
> > > [root@app100 kafka]# ./kafka_2.11-0.11.0.2/bin/zookeeper-shell.sh
> > > localhost:2181 <<< "get /brokers/ids/1"
> > >
> > > Connecting to localhost:2181
> > >
> > > Welcome to ZooKeeper!
> > >
> > > JLine support is disabled
> > >
> > >
> > > WATCHER::
> > >
> > >
> > > WatchedEvent state:SyncConnected type:None path:null
> > >
> > > {"listener_security_protocol_map":{"PLAINTEXT":"PLAINTEXT"}
> > > ,"endpoints":["PLAINTEXT://172.31.14.8:9092"],"jmx_port":
> > > 55555,"host":"172.31.14.8","timestamp":"1517569016562","
> > > port":9092,"version":4}
> > >
> > > cZxid = 0x21
> > >
> > > ctime = Fri Feb 02 10:56:56 UTC 2018
> > >
> > > mZxid = 0x21
> > >
> > > mtime = Fri Feb 02 10:56:56 UTC 2018
> > >
> > > pZxid = 0x21
> > >
> > > cversion = 0
> > >
> > > dataVersion = 0
> > >
> > > aclVersion = 0
> > >
> > > ephemeralOwner = 0x161562860970001
> > >
> > > dataLength = 195
> > >
> > > numChildren = 0
> > >
> > > Could you please throw some light on this as to what could be going
> wrong
> > > here?
> > >
> > > Thanks,
> > > Tony
> > >
> >
> >
> >
> > --
> > -- Guozhang
> >
>
--
-- Guozhang
Re: Kafka Streams : Connection to node -1 could not be established.
Broker may not be available.
Posted by Tony John <to...@gmail.com>.
Hi Guozhang,
Thanks for looking into this. Below are the stream config values.
INFO 2018-02-02 08:33:25.708 [main] org.apache.kafka.streams.StreamsConfig
- StreamsConfig values:
application.id = cv-v1
application.server =
bootstrap.servers = [172.31.10.35:9092, 172.31.14.8:9092]
buffered.records.per.partition = 1000
cache.max.bytes.buffering = 104857600
client.id = I2
commit.interval.ms = 30000
connections.max.idle.ms = 540000
default.key.serde = class
org.apache.kafka.common.serialization.Serdes$ByteArraySerde
default.timestamp.extractor = class
org.apache.kafka.streams.processor.FailOnInvalidTimestamp
default.value.serde = class
org.apache.kafka.common.serialization.Serdes$ByteArraySerde
key.serde = null
metadata.max.age.ms = 300000
metric.reporters = []
metrics.num.samples = 2
metrics.recording.level = DEBUG
metrics.sample.window.ms = 30000
num.standby.replicas = 1
num.stream.threads = 1
partition.grouper = class
org.apache.kafka.streams.processor.DefaultPartitionGrouper
poll.ms = 100
processing.guarantee = at_least_once
receive.buffer.bytes = 32768
reconnect.backoff.max.ms = 1000
reconnect.backoff.ms = 50
replication.factor = 2
request.timeout.ms = 40000
retry.backoff.ms = 100
rocksdb.config.setter = null
security.protocol = PLAINTEXT
send.buffer.bytes = 131072
state.cleanup.delay.ms = 600000
state.dir = /mnt/store/kafka-streams
timestamp.extractor = null
value.serde = null
windowstore.changelog.additional.retention.ms = 86400000
zookeeper.connect =
INFO 2018-02-02 08:33:25.870 [main] org.apache.kafka.streams.StreamsConfig
- StreamsConfig values:
application.id = pe-v1
application.server =
bootstrap.servers = [172.31.10.35:9092, 172.31.14.8:9092]
buffered.records.per.partition = 1000
cache.max.bytes.buffering = 2147483648
client.id = I2
commit.interval.ms = 30000
connections.max.idle.ms = 540000
default.key.serde = class
org.apache.kafka.common.serialization.Serdes$ByteArraySerde
default.timestamp.extractor = class
org.apache.kafka.streams.processor.FailOnInvalidTimestamp
default.value.serde = class
org.apache.kafka.common.serialization.Serdes$ByteArraySerde
key.serde = null
metadata.max.age.ms = 300000
metric.reporters = []
metrics.num.samples = 2
metrics.recording.level = DEBUG
metrics.sample.window.ms = 30000
num.standby.replicas = 1
num.stream.threads = 3
partition.grouper = class
org.apache.kafka.streams.processor.DefaultPartitionGrouper
poll.ms = 100
processing.guarantee = at_least_once
receive.buffer.bytes = 32768
reconnect.backoff.max.ms = 1000
reconnect.backoff.ms = 50
replication.factor = 2
request.timeout.ms = 40000
retry.backoff.ms = 100
rocksdb.config.setter = null
security.protocol = PLAINTEXT
send.buffer.bytes = 131072
state.cleanup.delay.ms = 600000
state.dir = /mnt/store/kafka-streams
timestamp.extractor = null
value.serde = null
windowstore.changelog.additional.retention.ms = 86400000
zookeeper.connect =
Please note there are 2 streams application running.
Apart from the Broker connectivity issue, I see the below logs as well.
What does that indicate and does it have any impact on the processing?
DEBUG 2018-02-05 11:06:07.369 [I2-StreamThread-5]
org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
[I2-StreamThread-5] processing latency 6694 < commit time 30000 for 10000
records. Adjusting up recordsProcessedBeforeCommit=44816
DEBUG 2018-02-05 11:06:07.518 [I2-StreamThread-3]
org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
[I2-StreamThread-3] processing latency 3684 < commit time 30000 for 10000
records. Adjusting up recordsProcessedBeforeCommit=81433
DEBUG 2018-02-05 11:06:07.562 [I2-StreamThread-4]
org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
[I2-StreamThread-4] processing latency 3620 < commit time 30000 for 10000
records. Adjusting up recordsProcessedBeforeCommit=82872
DEBUG 2018-02-05 11:06:09.838 [I2-StreamThread-7]
org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
[I2-StreamThread-7] processing latency 3843 < commit time 30000 for 10000
records. Adjusting up recordsProcessedBeforeCommit=78064
DEBUG 2018-02-05 11:06:10.073 [I2-StreamThread-3]
org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
[I2-StreamThread-3] processing latency 2552 < commit time 30000 for 7193
records. Adjusting up recordsProcessedBeforeCommit=84557
DEBUG 2018-02-05 11:06:10.209 [I2-StreamThread-4]
org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
[I2-StreamThread-4] processing latency 2645 < commit time 30000 for 7161
records. Adjusting up recordsProcessedBeforeCommit=81221
DEBUG 2018-02-05 11:06:11.940 [I2-StreamThread-5]
org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
[I2-StreamThread-5] processing latency 4568 < commit time 30000 for 7583
records. Adjusting up recordsProcessedBeforeCommit=49800
DEBUG 2018-02-05 11:06:12.538 [I2-StreamThread-7]
org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
[I2-StreamThread-7] processing latency 2698 < commit time 30000 for 6880
records. Adjusting up recordsProcessedBeforeCommit=76501
Thanks,
Tony
On Tue, Feb 6, 2018 at 3:21 AM, Guozhang Wang <wa...@gmail.com> wrote:
> Hello Tony,
>
>
> Could you share your Streams config values so that people can help further
> investigating your issue?
>
>
> Guozhang
>
>
> On Mon, Feb 5, 2018 at 12:00 AM, Tony John <to...@gmail.com>
> wrote:
>
> > Hi All,
> >
> > I have been running a streams application for sometime. The application
> > runs fine for sometime but after a day or two I see the below log getting
> > printed continuously on to the console.
> >
> > WARN 2018-02-05 02:50:04.060 [kafka-producer-network-thread |
> producer-1]
> > org.apache.kafka.clients.NetworkClient - Connection to node -1 could not
> > be
> > established. Broker may not be available.
> >
> > WARN 2018-02-05 02:50:04.160 [kafka-producer-network-thread |
> producer-1]
> > org.apache.kafka.clients.NetworkClient - Connection to node -1 could not
> > be
> > established. Broker may not be available.
> >
> > WARN 2018-02-05 02:50:04.261 [kafka-producer-network-thread |
> producer-1]
> > org.apache.kafka.clients.NetworkClient - Connection to node -1 could not
> > be
> > established. Broker may not be available.
> >
> > WARN 2018-02-05 02:50:04.311 [kafka-producer-network-thread |
> producer-1]
> > org.apache.kafka.clients.NetworkClient - Connection to node -1 could not
> > be
> > established. Broker may not be available.
> >
> > WARN 2018-02-05 02:50:04.361 [kafka-producer-network-thread |
> producer-1]
> > org.apache.kafka.clients.NetworkClient - Connection to node -1 could not
> > be
> > established. Broker may not be available.
> >
> > WARN 2018-02-05 02:50:04.411 [kafka-producer-network-thread |
> producer-1]
> > org.apache.kafka.clients.NetworkClient - Connection to node -1 could not
> > be
> > established. Broker may not be available.
> >
> > At this time, though the application is able to process the messages, I
> > could also see lag building up in the consumers and the processing time
> for
> > a batch has increased 15 folds.
> >
> > I am using a single zoo-keeper instance with 2 brokers and 4 application
> > instances. I checked the broker and zoo-keeper status, they are all
> running
> > fine as I could see. I have also verified the connectivity between the
> > application and broker instances using telnet and it seems intact. The
> > kafka broker and streams/client versions are 0.11.0.2. Results of broker
> > status results from zoo-keeper below
> >
> >
> > [root@app100 kafka]# echo dump | nc localhost 2181
> >
> > SessionTracker dump:
> >
> > Session Sets (3):
> >
> > 0 expire at Mon Feb 05 06:16:39 UTC 2018:
> >
> > 1 expire at Mon Feb 05 06:16:42 UTC 2018:
> >
> > 0x161562860970001
> >
> > 1 expire at Mon Feb 05 06:16:45 UTC 2018:
> >
> > 0x161562860970000
> >
> > ephemeral nodes dump:
> >
> > Sessions with Ephemerals (2):
> >
> > 0x161562860970000:
> >
> > /brokers/ids/0
> >
> > /controller
> >
> > 0x161562860970001:
> >
> > /brokers/ids/1
> >
> > [root@app100 kafka]# ./kafka_2.11-0.11.0.2/bin/zookeeper-shell.sh
> > localhost:2181 <<< "get /brokers/ids/0"
> >
> > Connecting to localhost:2181
> >
> > Welcome to ZooKeeper!
> >
> > JLine support is disabled
> >
> >
> > WATCHER::
> >
> >
> > WatchedEvent state:SyncConnected type:None path:null
> >
> > {"listener_security_protocol_map":{"PLAINTEXT":"PLAINTEXT"}
> > ,"endpoints":["PLAINTEXT://172.31.10.35:9092"],"jmx_port":
> > 55555,"host":"172.31.10.35","timestamp":"1517569007467","
> > port":9092,"version":4}
> >
> > cZxid = 0x1c
> >
> > ctime = Fri Feb 02 10:56:47 UTC 2018
> >
> > mZxid = 0x1c
> >
> > mtime = Fri Feb 02 10:56:47 UTC 2018
> >
> > pZxid = 0x1c
> >
> > cversion = 0
> >
> > dataVersion = 0
> >
> > aclVersion = 0
> >
> > ephemeralOwner = 0x161562860970000
> >
> > dataLength = 197
> >
> > numChildren = 0
> >
> > [root@app100 kafka]# ./kafka_2.11-0.11.0.2/bin/zookeeper-shell.sh
> > localhost:2181 <<< "get /brokers/ids/1"
> >
> > Connecting to localhost:2181
> >
> > Welcome to ZooKeeper!
> >
> > JLine support is disabled
> >
> >
> > WATCHER::
> >
> >
> > WatchedEvent state:SyncConnected type:None path:null
> >
> > {"listener_security_protocol_map":{"PLAINTEXT":"PLAINTEXT"}
> > ,"endpoints":["PLAINTEXT://172.31.14.8:9092"],"jmx_port":
> > 55555,"host":"172.31.14.8","timestamp":"1517569016562","
> > port":9092,"version":4}
> >
> > cZxid = 0x21
> >
> > ctime = Fri Feb 02 10:56:56 UTC 2018
> >
> > mZxid = 0x21
> >
> > mtime = Fri Feb 02 10:56:56 UTC 2018
> >
> > pZxid = 0x21
> >
> > cversion = 0
> >
> > dataVersion = 0
> >
> > aclVersion = 0
> >
> > ephemeralOwner = 0x161562860970001
> >
> > dataLength = 195
> >
> > numChildren = 0
> >
> > Could you please throw some light on this as to what could be going wrong
> > here?
> >
> > Thanks,
> > Tony
> >
>
>
>
> --
> -- Guozhang
>
Re: Kafka Streams : Connection to node -1 could not be established.
Broker may not be available.
Posted by Guozhang Wang <wa...@gmail.com>.
Hello Tony,
Could you share your Streams config values so that people can help further
investigating your issue?
Guozhang
On Mon, Feb 5, 2018 at 12:00 AM, Tony John <to...@gmail.com> wrote:
> Hi All,
>
> I have been running a streams application for sometime. The application
> runs fine for sometime but after a day or two I see the below log getting
> printed continuously on to the console.
>
> WARN 2018-02-05 02:50:04.060 [kafka-producer-network-thread | producer-1]
> org.apache.kafka.clients.NetworkClient - Connection to node -1 could not
> be
> established. Broker may not be available.
>
> WARN 2018-02-05 02:50:04.160 [kafka-producer-network-thread | producer-1]
> org.apache.kafka.clients.NetworkClient - Connection to node -1 could not
> be
> established. Broker may not be available.
>
> WARN 2018-02-05 02:50:04.261 [kafka-producer-network-thread | producer-1]
> org.apache.kafka.clients.NetworkClient - Connection to node -1 could not
> be
> established. Broker may not be available.
>
> WARN 2018-02-05 02:50:04.311 [kafka-producer-network-thread | producer-1]
> org.apache.kafka.clients.NetworkClient - Connection to node -1 could not
> be
> established. Broker may not be available.
>
> WARN 2018-02-05 02:50:04.361 [kafka-producer-network-thread | producer-1]
> org.apache.kafka.clients.NetworkClient - Connection to node -1 could not
> be
> established. Broker may not be available.
>
> WARN 2018-02-05 02:50:04.411 [kafka-producer-network-thread | producer-1]
> org.apache.kafka.clients.NetworkClient - Connection to node -1 could not
> be
> established. Broker may not be available.
>
> At this time, though the application is able to process the messages, I
> could also see lag building up in the consumers and the processing time for
> a batch has increased 15 folds.
>
> I am using a single zoo-keeper instance with 2 brokers and 4 application
> instances. I checked the broker and zoo-keeper status, they are all running
> fine as I could see. I have also verified the connectivity between the
> application and broker instances using telnet and it seems intact. The
> kafka broker and streams/client versions are 0.11.0.2. Results of broker
> status results from zoo-keeper below
>
>
> [root@app100 kafka]# echo dump | nc localhost 2181
>
> SessionTracker dump:
>
> Session Sets (3):
>
> 0 expire at Mon Feb 05 06:16:39 UTC 2018:
>
> 1 expire at Mon Feb 05 06:16:42 UTC 2018:
>
> 0x161562860970001
>
> 1 expire at Mon Feb 05 06:16:45 UTC 2018:
>
> 0x161562860970000
>
> ephemeral nodes dump:
>
> Sessions with Ephemerals (2):
>
> 0x161562860970000:
>
> /brokers/ids/0
>
> /controller
>
> 0x161562860970001:
>
> /brokers/ids/1
>
> [root@app100 kafka]# ./kafka_2.11-0.11.0.2/bin/zookeeper-shell.sh
> localhost:2181 <<< "get /brokers/ids/0"
>
> Connecting to localhost:2181
>
> Welcome to ZooKeeper!
>
> JLine support is disabled
>
>
> WATCHER::
>
>
> WatchedEvent state:SyncConnected type:None path:null
>
> {"listener_security_protocol_map":{"PLAINTEXT":"PLAINTEXT"}
> ,"endpoints":["PLAINTEXT://172.31.10.35:9092"],"jmx_port":
> 55555,"host":"172.31.10.35","timestamp":"1517569007467","
> port":9092,"version":4}
>
> cZxid = 0x1c
>
> ctime = Fri Feb 02 10:56:47 UTC 2018
>
> mZxid = 0x1c
>
> mtime = Fri Feb 02 10:56:47 UTC 2018
>
> pZxid = 0x1c
>
> cversion = 0
>
> dataVersion = 0
>
> aclVersion = 0
>
> ephemeralOwner = 0x161562860970000
>
> dataLength = 197
>
> numChildren = 0
>
> [root@app100 kafka]# ./kafka_2.11-0.11.0.2/bin/zookeeper-shell.sh
> localhost:2181 <<< "get /brokers/ids/1"
>
> Connecting to localhost:2181
>
> Welcome to ZooKeeper!
>
> JLine support is disabled
>
>
> WATCHER::
>
>
> WatchedEvent state:SyncConnected type:None path:null
>
> {"listener_security_protocol_map":{"PLAINTEXT":"PLAINTEXT"}
> ,"endpoints":["PLAINTEXT://172.31.14.8:9092"],"jmx_port":
> 55555,"host":"172.31.14.8","timestamp":"1517569016562","
> port":9092,"version":4}
>
> cZxid = 0x21
>
> ctime = Fri Feb 02 10:56:56 UTC 2018
>
> mZxid = 0x21
>
> mtime = Fri Feb 02 10:56:56 UTC 2018
>
> pZxid = 0x21
>
> cversion = 0
>
> dataVersion = 0
>
> aclVersion = 0
>
> ephemeralOwner = 0x161562860970001
>
> dataLength = 195
>
> numChildren = 0
>
> Could you please throw some light on this as to what could be going wrong
> here?
>
> Thanks,
> Tony
>
--
-- Guozhang