Hello.
I've got a local virtual development environment, with:
- kafka 0.10.1.1
- java version "1.8.0_121"
I don't need anything special, this is just for trial, so I set up zk and
kafka and the stream processor to use /tmp for data, log and state.
It's not persistent, but I can always try new things, with no memory
effect at all. :)
Issue1:
- I coldstart zk (no previous history whatsoever)
- I coldstart kafka (no previous history whatsoever)
- Seems fine.
- I coldstart my stream api node
My app writes these to stdout for the first 2 seconds:
[2017-01-31 12:49:16,062] WARN [StreamThread-1] Error while fetching
metadata with correlation id 1 :
{mousetracker-pixelprocessor-Count-repartition=LEADER_NOT_AVAILABLE,
mousetracker-ioclient2backend=LEADER_NOT_AVAILABLE}
(org.apache.kafka.clients.NetworkClient)
... >8 cut here .... 8<....
[2017-01-31 12:49:19,593] WARN [StreamThread-1] Error while fetching
metadata with correlation id 50 :
{mousetracker-ioclient2backend=LEADER_NOT_AVAILABLE}
(org.apache.kafka.clients.NetworkClient)
(note, that ODD correlation id's except 1 are missing!)
At the same time, kafka does not have any warnings, it just takes some time
(like 2-3 seconds) until it gets all the partitions for all the __offset
topics done.)
2017-01-31 12:49:15,711] INFO Topic creation
{"version":1,"partitions":{"0":[0]}} (kafka.admin.AdminUtils$)
[2017-01-31 12:49:15,765] INFO [KafkaApi-0] Auto creation of topic
mousetracker-pixelprocessor-Count-repartition with 1 partitions and
replication factor 1 is successful (kafka.server.KafkaApis)
[2017-01-31 12:49:15,829] INFO Topic creation
{"version":1,"partitions":{"0":[0]}} (kafka.admin.AdminUtils$)
[2017-01-31 12:49:15,832] INFO [KafkaApi-0] Auto creation of topic
mousetracker-ioclient2backend with 1 partitions and replication factor 1 is
successful (kafka.server.KafkaApis)
[2017-01-31 12:49:15,964] INFO Topic creation
{"version":1,"partitions":{"45":[0],"34":[0],"12":[0],"8":[0],"19":[0],"23":[0],"4":[0],"40":[0],"15":[0],"11":[0],"9":[0],"44":[0],"33":[0],"22":[0],"26":[0],"37":[0],"13":[0],"46":[0],"24":[0],"35":[0],"16":[0],"5":[0],"10":[0],"48":[0],"21":[0],"43":[0],"32":[0],"49":[0],"6":[0],"36":[0],"1":[0],"39":[0],"17":[0],"25":[0],"14":[0],"47":[0],"31":[0],"42":[0],"0":[0],"20":[0],"27":[0],"2":[0],"38":[0],"18":[0],"30":[0],"7":[0],"29":[0],"41":[0],"3":[0],"28":[0]}}
(kafka.admin.AdminUtils$)
[2017-01-31 12:49:16,000] INFO [KafkaApi-0] Auto creation of topic
__consumer_offsets with 50 partitions and replication factor 1 is
successful (kafka.server.KafkaApis)
Meanwhile in zookeeper's log:
[2017-01-31 12:49:15,451] INFO Accepted socket connection from /
127.0.0.1:54366 (org.apache.zookeeper.server.NIOServerCnxnFactory)
[2017-01-31 12:49:15,454] INFO Client attempting to establish new session
at /127.0.0.1:54366 (org.apache.zookeeper.server.ZooKeeperServer)
[2017-01-31 12:49:15,456] INFO Established session 0x159f48f42d40001 with
negotiated timeout 30000 for client /127.0.0.1:54366
(org.apache.zookeeper.server.ZooKeeperServer)
[2017-01-31 12:49:15,706] INFO Got user-level KeeperException when
processing sessionid:0x159f48f42d40000 type:setData cxid:0x4a zxid:0x1c
txntype:-1 reqpath:n/a Error
Path:/config/topics/mousetracker-pixelprocessor-Count-repartition
Error:KeeperErrorCode = NoNode for
/config/topics/mousetracker-pixelprocessor-Count-repartition
(org.apache.zookeeper.server.PrepRequestProcessor)
[2017-01-31 12:49:15,708] INFO Got user-level KeeperException when
processing sessionid:0x159f48f42d40000 type:create cxid:0x4b zxid:0x1d
txntype:-1 reqpath:n/a Error Path:/config/topics Error:KeeperErrorCode =
NodeExists for /config/topics
(org.apache.zookeeper.server.PrepRequestProcessor)
[2017-01-31 12:49:15,804] INFO Got user-level KeeperException when
processing sessionid:0x159f48f42d40000 type:setData cxid:0x55 zxid:0x20
txntype:-1 reqpath:n/a Error
Path:/config/topics/mousetracker-ioclient2backend Error:KeeperErrorCode =
NoNode for /config/topics/mousetracker-ioclient2backend
(org.apache.zookeeper.server.PrepRequestProcessor)
and this goest for like 2-3 seconds also.
I do believe, that the stream api client should not threw any warnings even
if it takes some time for the server to prepare the environment. (Also
neither ZK or KAFKA has errors in their logs, but ZK has INFO messages
about exceptions, I find strange a little.)
Usually the app works fine after this rough takeoff, but here comes the
"sometimes not" part.
Issue2:
=======
- Coldstart ZK
- Coldstart Kafka
- Coldstart stream api client
- The stream api client goes mayhem (SIGTERM won't stop it), it's like an
endless loop
- ZK goes into extreme endless loop with 20 messages/sec:
[2017-01-31 16:58:01,433] INFO Got user-level KeeperException when
processing sessionid:0x159f55d4d370001 type:create cxid:0x19f02 zxid:0xf246
txntype:-1 reqpath:n/a Error
Path:/admin/delete_topics/mousetracker-pixelprocessor-Count-repartition
Error:KeeperErrorCode = NodeExists for
/admin/delete_topics/mousetracker-pixelprocessor-Count-repartition
(org.apache.zookeeper.server.PrepRequestProcessor)
[2017-01-31 16:58:01,434] INFO Got user-level KeeperException when
processing sessionid:0x159f55d4d370001 type:create cxid:0x19f04 zxid:0xf247
txntype:-1 reqpath:n/a Error
Path:/admin/delete_topics/mousetracker-pixelprocessor-Count-repartition
Error:KeeperErrorCode = NodeExists for
/admin/delete_topics/mousetracker-pixelprocessor-Count-repartition
(org.apache.zookeeper.server.PrepRequestProcessor)
[2017-01-31 16:58:01,435] INFO Got user-level KeeperException when
processing sessionid:0x159f55d4d370001 type:create cxid:0x19f06 zxid:0xf248
txntype:-1 reqpath:n/a Error
Path:/admin/delete_topics/mousetracker-pixelprocessor-Count-repartition
Error:KeeperErrorCode = NodeExists for
/admin/delete_topics/mousetracker-pixelprocessor-Count-repartition
(org.apache.zookeeper.server.PrepRequestProcessor)
[2017-01-31 16:58:01,437] INFO Got user-level KeeperException when
processing sessionid:0x159f55d4d370001 type:create cxid:0x19f08 zxid:0xf249
txntype:-1 reqpath:n/a Error
Path:/admin/delete_topics/mousetracker-pixelprocessor-Count-repartition
Error:KeeperErrorCode = NodeExists for
/admin/delete_topics/mousetracker-pixelprocessor-Count-repartition
(org.apache.zookeeper.server.PrepRequestProcessor)
The thing is that I did not even produce one single record ever.
So there's no incoming data into kafka, no data on the input topic of the
stream client, so the expected result would be a quiet startup with
messages of "incoming connection" and "created empty topic fine", than
nothing happening till the end of time.
The stream client does nothing, just an aggregate based on key, and
outputs that on a topic, no threading, or tweaking under the hood, not even
processor api usage or anything fancy.
Any ideas?
Peter
ps.: since then I've lowered the offsets.topic.num.partitions = 50 to 2, to
ease the startup problem
