I think this might be an issue related to having
auto.create.topics.enabled=true (the default).
Try setting auto.create.topics.enabled=false in server.properties.
On Tue, 31 Jan 2017 at 17:29 Peter Kopias <kopias.pe...@gmail.com> wrote:
> 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
>
