I am running on windows. I am programmatically (no scripts) starting a zk,
2 brokers, 2 consumers and a producer, in this order but the first 3 at
once, then the other 3 at once, all with a nonexistent topic.
Here's the pertinent log for the producer (with other stuff mixed in, no
doubt):
start production: com.dish.des.msgs.notifications.StartProduction@d27b1b3
{2013-05-08 23:53:07,187} INFO [local-vat] (Logging.scala:67) - Fetching
metadata with correlation id 0 for 1 topic(s) Set(robert_v_2x0)
{2013-05-08 23:53:07,206} DEBUG [local-vat] (Logging.scala:51) - Created
socket with SO_TIMEOUT = 1500 (requested 1500), SO_RCVBUF = 8192 (requested
-1), SO_SNDBUF = 102400 (requested 102400).
{2013-05-08 23:53:07,207} DEBUG [kafka-acceptor] (Logging.scala:51) -
Accepted connection from /127.0.0.1 on /127.0.0.1:9092. sendBufferSize
[actual|requested]: [1048576|1048576] recvBufferSize [actual|requested]:
[1048576|1048576]
{2013-05-08 23:53:07,208} DEBUG [kafka-processor-9092-0] (Logging.scala:51)
- Processor 0 listening to new connection from /127.0.0.1:63245
{2013-05-08 23:53:07,209} INFO [local-vat] (Logging.scala:67) - Connected
to localhost:9092 for producing
{2013-05-08 23:53:07,256} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:78) - Processing request::
sessionid:0x13e87d872090002 type:ping cxid:0xfffffffffffffffe
zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-08 23:53:07,256} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:160) - sessionid:0x13e87d872090002 type:ping
cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-08 23:53:07,257} DEBUG [main-SendThread(localhost:2181)]
(ClientCnxn.java:758) - Got ping response for sessionid: 0x13e87d872090002
after 2ms
{2013-05-08 23:53:07,279} DEBUG [kafka-request-handler-1] (Logging.scala:51)
- [Kafka Request Handler 1 on Broker 0], handles request
Request(0,sun.nio.ch.SelectionKeyImpl@1261db2b,null,1368078787227,/127.0.0.1
:63245)
{2013-05-08 23:53:07,290} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:78) - Processing request::
sessionid:0x13e87d872090000 type:exists cxid:0x26 zxid:0xfffffffffffffffe
txntype:unknown reqpath:/brokers/topics/robert_v_2x0
{2013-05-08 23:53:07,291} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:160) - sessionid:0x13e87d872090000 type:exists
cxid:0x26 zxid:0xfffffffffffffffe txntype:unknown
reqpath:/brokers/topics/robert_v_2x0
{2013-05-08 23:53:07,293} DEBUG [Thread-1-SendThread(localhost:2181)]
(ClientCnxn.java:838) - Reading reply sessionid:0x13e87d872090000, packet::
clientPath:null serverPath:null finished:false header:: 38,3 replyHeader::
38,955,-101 request:: '/brokers/topics/robert_v_2x0,F response::
{2013-05-08 23:53:07,373} ERROR [kafka-request-handler-1]
(Logging.scala:102) - [KafkaApi-0] Error while retrieving topic metadata
java.lang.NoClassDefFoundError: joptsimple/OptionSpec
at
kafka.server.KafkaApis$$anonfun$handleTopicMetadataRequest$1.apply(KafkaApis
.scala:411)
at
kafka.server.KafkaApis$$anonfun$handleTopicMetadataRequest$1.apply(KafkaApis
.scala:403)
at scala.collection.immutable.Set$Set1.foreach(Set.scala:81)
at
kafka.server.KafkaApis.handleTopicMetadataRequest(KafkaApis.scala:402)
at kafka.server.KafkaApis.handle(KafkaApis.scala:63)
at kafka.server.KafkaRequestHandler.run(KafkaRequestHandler.scala:41)
at java.lang.Thread.run(Thread.java:722)
Caused by: java.lang.ClassNotFoundException: joptsimple.OptionSpec
at java.net.URLClassLoader$1.run(URLClassLoader.java:366)
at java.net.URLClassLoader$1.run(URLClassLoader.java:355)
at java.security.AccessController.doPrivileged(Native Method)
at java.net.URLClassLoader.findClass(URLClassLoader.java:354)
at java.lang.ClassLoader.loadClass(ClassLoader.java:423)
at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:308)
at java.lang.ClassLoader.loadClass(ClassLoader.java:356)
... 7 more
{2013-05-08 23:53:07,388} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:78) - Processing request::
sessionid:0x13e87d872090003 type:ping cxid:0xfffffffffffffffe
zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-08 23:53:07,393} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:160) - sessionid:0x13e87d872090003 type:ping
cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-08 23:53:07,395} DEBUG [main-SendThread(localhost:2181)]
(ClientCnxn.java:758) - Got ping response for sessionid: 0x13e87d872090003
after 8ms
{2013-05-08 23:53:07,557} INFO [local-vat] (Logging.scala:67) -
Disconnecting from localhost:9092
{2013-05-08 23:53:07,570} DEBUG [local-vat] (Logging.scala:51) -
Successfully fetched metadata for 1 topic(s) Set(robert_v_2x0)
{2013-05-08 23:53:07,583} DEBUG [local-vat] (Logging.scala:51) - Getting
broker partition info for topic robert_v_2x0
{2013-05-08 23:53:07,600} INFO [local-vat] (Logging.scala:67) - Fetching
metadata with correlation id 1 for 1 topic(s) Set(robert_v_2x0)
{2013-05-08 23:53:07,605} DEBUG [kafka-acceptor] (Logging.scala:51) -
Accepted connection from /127.0.0.1 on /127.0.0.1:9092. sendBufferSize
[actual|requested]: [1048576|1048576] recvBufferSize [actual|requested]:
[1048576|1048576]
{2013-05-08 23:53:07,606} DEBUG [kafka-processor-9092-1] (Logging.scala:51)
- Processor 1 listening to new connection from /127.0.0.1:63248
{2013-05-08 23:53:07,588} INFO [kafka-processor-9092-0] (Logging.scala:67)
- Closing socket connection to /127.0.0.1.
{2013-05-08 23:53:07,609} DEBUG [kafka-processor-9092-0] (Logging.scala:51)
- Closing connection from /127.0.0.1:63245
{2013-05-08 23:53:07,606} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:78) - Processing request::
sessionid:0x13e87d872090001 type:ping cxid:0xfffffffffffffffe
zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-08 23:53:07,618} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:160) - sessionid:0x13e87d872090001 type:ping
cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-08 23:53:07,606} DEBUG [local-vat] (Logging.scala:51) - Created
socket with SO_TIMEOUT = 1500 (requested 1500), SO_RCVBUF = 8192 (requested
-1), SO_SNDBUF = 102400 (requested 102400).
{2013-05-08 23:53:07,620} INFO [local-vat] (Logging.scala:67) - Connected
to localhost:9092 for producing
{2013-05-08 23:53:07,622} DEBUG [Thread-2-SendThread(localhost:2181)]
(ClientCnxn.java:758) - Got ping response for sessionid: 0x13e87d872090001
after 37ms
{2013-05-08 23:53:07,623} DEBUG [kafka-request-handler-0] (Logging.scala:51)
- [Kafka Request Handler 0 on Broker 0], handles request
Request(1,sun.nio.ch.SelectionKeyImpl@81331d5,null,1368078787622,/127.0.0.1:
63248)
{2013-05-08 23:53:07,626} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:78) - Processing request::
sessionid:0x13e87d872090000 type:exists cxid:0x27 zxid:0xfffffffffffffffe
txntype:unknown reqpath:/brokers/topics/robert_v_2x0
{2013-05-08 23:53:07,626} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:160) - sessionid:0x13e87d872090000 type:exists
cxid:0x27 zxid:0xfffffffffffffffe txntype:unknown
reqpath:/brokers/topics/robert_v_2x0
{2013-05-08 23:53:07,629} DEBUG [Thread-1-SendThread(localhost:2181)]
(ClientCnxn.java:838) - Reading reply sessionid:0x13e87d872090000, packet::
clientPath:null serverPath:null finished:false header:: 39,3 replyHeader::
39,955,-101 request:: '/brokers/topics/robert_v_2x0,F response::
{2013-05-08 23:53:07,632} ERROR [kafka-request-handler-0]
(Logging.scala:102) - [KafkaApi-0] Error while retrieving topic metadata
java.lang.NoClassDefFoundError: joptsimple/OptionSpec
at
kafka.server.KafkaApis$$anonfun$handleTopicMetadataRequest$1.apply(KafkaApis
.scala:411)
at
kafka.server.KafkaApis$$anonfun$handleTopicMetadataRequest$1.apply(KafkaApis
.scala:403)
at scala.collection.immutable.Set$Set1.foreach(Set.scala:81)
at
kafka.server.KafkaApis.handleTopicMetadataRequest(KafkaApis.scala:402)
at kafka.server.KafkaApis.handle(KafkaApis.scala:63)
at kafka.server.KafkaRequestHandler.run(KafkaRequestHandler.scala:41)
at java.lang.Thread.run(Thread.java:722)
Caused by: java.lang.ClassNotFoundException: joptsimple.OptionSpec
at java.net.URLClassLoader$1.run(URLClassLoader.java:366)
at java.net.URLClassLoader$1.run(URLClassLoader.java:355)
at java.security.AccessController.doPrivileged(Native Method)
at java.net.URLClassLoader.findClass(URLClassLoader.java:354)
at java.lang.ClassLoader.loadClass(ClassLoader.java:423)
at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:308)
at java.lang.ClassLoader.loadClass(ClassLoader.java:356)
... 7 more
{2013-05-08 23:53:07,637} INFO [local-vat] (Logging.scala:67) -
Disconnecting from localhost:9092
{2013-05-08 23:53:07,639} DEBUG [local-vat] (Logging.scala:51) -
Successfully fetched metadata for 1 topic(s) Set(robert_v_2x0)
{2013-05-08 23:53:07,639} INFO [kafka-processor-9092-1] (Logging.scala:67)
- Closing socket connection to /127.0.0.1.
{2013-05-08 23:53:07,640} DEBUG [kafka-processor-9092-1] (Logging.scala:51)
- Closing connection from /127.0.0.1:63248
{2013-05-08 23:53:07,644} ERROR [local-vat] (Logging.scala:102) - Failed to
collate messages by topic, partition due to
kafka.common.KafkaException: Failed to fetch topic metadata for topic:
robert_v_2x0
at
kafka.producer.BrokerPartitionInfo.getBrokerPartitionInfo(BrokerPartitionInf
o.scala:53)
at
kafka.producer.async.DefaultEventHandler.kafka$producer$async$DefaultEventHa
ndler$$getPartitionListForTopic(DefaultEventHandler.scala:185)
at
kafka.producer.async.DefaultEventHandler$$anonfun$partitionAndCollate$1.appl
y(DefaultEventHandler.scala:149)
at
kafka.producer.async.DefaultEventHandler$$anonfun$partitionAndCollate$1.appl
y(DefaultEventHandler.scala:148)
at
scala.collection.mutable.ResizableArray$class.foreach(ResizableArray.scala:5
7)
at scala.collection.mutable.ArrayBuffer.foreach(ArrayBuffer.scala:43)
at
kafka.producer.async.DefaultEventHandler.partitionAndCollate(DefaultEventHan
dler.scala:148)
at
kafka.producer.async.DefaultEventHandler.dispatchSerializedData(DefaultEvent
Handler.scala:94)
at
kafka.producer.async.DefaultEventHandler.handle(DefaultEventHandler.scala:72
)
at kafka.producer.Producer.send(Producer.scala:74)
at kafka.javaapi.producer.Producer.send(Producer.scala:32)
at
com.dish.des.kafka.KafkaTopicProducer.send(KafkaTopicProducer.java:32)
at
com.dish.des.kafka.KafkaTopicProducer.publish(KafkaTopicProducer.java:27)
at com.dish.des.system.TestRunProducer.send(TestRunProducer.java:48)
at com.dish.des.system.TestRunProducer.run(TestRunProducer.java:41)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57
)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl
.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at
org.reefedjib.murmur.lib.MessageSend$Sender.privateSendIt(MessageSend.java:2
59)
at
org.reefedjib.murmur.lib.MessageSend$Sender.sendIt(MessageSend.java:245)
at org.reefedjib.murmur.lib.MessageSend.sendIt(MessageSend.java:146)
at org.reefedjib.murmur.lib.MessageSend.run(MessageSend.java:85)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$
201(ScheduledThreadPoolExecutor.java:178)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Sch
eduledThreadPoolExecutor.java:292)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:11
45)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
15)
at java.lang.Thread.run(Thread.java:722)
java.lang.reflect.InvocationTargetException
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57
)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl
.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at
org.reefedjib.murmur.lib.MessageSend$Sender.privateSendIt(MessageSend.java:2
59)
at
org.reefedjib.murmur.lib.MessageSend$Sender.sendIt(MessageSend.java:245)
at org.reefedjib.murmur.lib.MessageSend.sendIt(MessageSend.java:146)
at org.reefedjib.murmur.lib.MessageSend.run(MessageSend.java:85)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$
201(ScheduledThreadPoolExecutor.java:178)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Sch
eduledThreadPoolExecutor.java:292)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:11
45)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
15)
at java.lang.Thread.run(Thread.java:722)
Caused by: kafka.common.KafkaException: Failed to fetch topic metadata for
topic: robert_v_2x0
at
kafka.producer.BrokerPartitionInfo.getBrokerPartitionInfo(BrokerPartitionInf
o.scala:53)
at
kafka.producer.async.DefaultEventHandler.kafka$producer$async$DefaultEventHa
ndler$$getPartitionListForTopic(DefaultEventHandler.scala:185)
at
kafka.producer.async.DefaultEventHandler$$anonfun$partitionAndCollate$1.appl
y(DefaultEventHandler.scala:149)
at
kafka.producer.async.DefaultEventHandler$$anonfun$partitionAndCollate$1.appl
y(DefaultEventHandler.scala:148)
at
scala.collection.mutable.ResizableArray$class.foreach(ResizableArray.scala:5
7)
at scala.collection.mutable.ArrayBuffer.foreach(ArrayBuffer.scala:43)
at
kafka.producer.async.DefaultEventHandler.partitionAndCollate(DefaultEventHan
dler.scala:148)
at
kafka.producer.async.DefaultEventHandler.dispatchSerializedData(DefaultEvent
Handler.scala:94)
at
kafka.producer.async.DefaultEventHandler.handle(DefaultEventHandler.scala:72
)
at kafka.producer.Producer.send(Producer.scala:74)
at kafka.javaapi.producer.Producer.send(Producer.scala:32)
at
com.dish.des.kafka.KafkaTopicProducer.send(KafkaTopicProducer.java:32)
at
com.dish.des.kafka.KafkaTopicProducer.publish(KafkaTopicProducer.java:27)
at com.dish.des.system.TestRunProducer.send(TestRunProducer.java:48)
at com.dish.des.system.TestRunProducer.run(TestRunProducer.java:41)
... 16 more
This is followed by nothing but:
{2013-05-09 00:01:10,399} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:78) - Processing request::
sessionid:0x13e87e0a6800001 type:ping cxid:0xfffffffffffffffe
zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-09 00:01:10,399} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:160) - sessionid:0x13e87e0a6800001 type:ping
cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-09 00:01:10,401} DEBUG [Thread-2-SendThread(localhost:2181)]
(ClientCnxn.java:758) - Got ping response for sessionid: 0x13e87e0a6800001
after 2ms
{2013-05-09 00:01:10,838} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:78) - Processing request::
sessionid:0x13e87e0a6800002 type:ping cxid:0xfffffffffffffffe
zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-09 00:01:10,839} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:160) - sessionid:0x13e87e0a6800002 type:ping
cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-09 00:01:10,842} DEBUG [main-SendThread(localhost:2181)]
(ClientCnxn.java:758) - Got ping response for sessionid: 0x13e87e0a6800002
after 5ms
{2013-05-09 00:01:10,953} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:78) - Processing request::
sessionid:0x13e87e0a6800003 type:ping cxid:0xfffffffffffffffe
zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-09 00:01:10,956} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:160) - sessionid:0x13e87e0a6800003 type:ping
cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-09 00:01:10,957} DEBUG [main-SendThread(localhost:2181)]
(ClientCnxn.java:758) - Got ping response for sessionid: 0x13e87e0a6800003
after 8ms
{2013-05-09 00:01:11,288} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:78) - Processing request::
sessionid:0x13e87e0a6800000 type:ping cxid:0xfffffffffffffffe
zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-09 00:01:11,289} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:160) - sessionid:0x13e87e0a6800000 type:ping
cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-09 00:01:11,289} DEBUG [Thread-1-SendThread(localhost:2181)]
(ClientCnxn.java:758) - Got ping response for sessionid: 0x13e87e0a6800000
after 2ms
{2013-05-09 00:01:11,743} DEBUG [kafka-logflusher-1] (Logging.scala:51) -
[Log Manager on Broker 1] Checking for dirty logs to flush...
{2013-05-09 00:01:12,082} DEBUG [kafka-logflusher-1] (Logging.scala:51) -
[Log Manager on Broker 0] Checking for dirty logs to flush...
{2013-05-09 00:01:12,400} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:78) - Processing request::
sessionid:0x13e87e0a6800001 type:ping cxid:0xfffffffffffffffe
zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-09 00:01:12,400} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:160) - sessionid:0x13e87e0a6800001 type:ping
cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-09 00:01:12,401} DEBUG [Thread-2-SendThread(localhost:2181)]
(ClientCnxn.java:758) - Got ping response for sessionid: 0x13e87e0a6800001
after 2ms
{2013-05-09 00:01:12,838} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:78) - Processing request::
sessionid:0x13e87e0a6800002 type:ping cxid:0xfffffffffffffffe
zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-09 00:01:12,839} DEBUG [SyncThread:0]
(FinalRequestProcessor.java:160) - sessionid:0x13e87e0a6800002 type:ping
cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-09 00:01:12,840} DEBUG [main-SendThread(localhost:2181)]
(ClientCnxn.java:758) - Got ping response for sessionid: 0x13e87e0a6800002
after 3ms
thanks,
rob
