Thanks, Jun. Adding that jar got me further along but there is an issue with the following, probably a windows issue. I ran twice, once after the other was done. Here are the exceptions I got in each run:thanks,
rob
first run:
{2013-05-09 23:52:14,358} DEBUG [kafka-request-handler-1] (Logging.scala:59) - Error while fetching metadata for partition [robert_v_2x0,0]
kafka.common.LeaderNotAvailableException: No leader exists for partition 0
{2013-05-09 23:52:15,369} ERROR [kafka-request-handler-1] (ReplicaManager.scala:229) - Error on broker 0 while processing LeaderAndIsr request correlationId 5 received from controller 1 epoch 1 for partition (robert_v_2x0,0)
java.util.NoSuchElementException: key not found: \tmp\kafka0-logs
{2013-05-09 23:52:16,995} ERROR [local-vat] (Logging.scala:96) - Failed to send requests for topics robert_v_2x0 with correlation ids in [0,11]
java.lang.reflect.InvocationTargetException
Caused by: kafka.common.FailedToSendMessageException: Failed to send messages after 3 tries.
second run:
{2013-05-10 00:03:39,674} DEBUG [Thread-1] (Logging.scala:51) - Partition map for /brokers/topics/robert_v_2x0 is Map(0 -> List(0))
{2013-05-10 00:03:40,062} ERROR [kafka-request-handler-0] (ReplicaManager.scala:229) - Error on broker 0 while processing LeaderAndIsr request correlationId 0 received from controller 0 epoch 4 for partition (robert_v_2x0,0)
java.util.NoSuchElementException: key not found: \tmp\kafka0-logs
{2013-05-10 00:03:40,341} ERROR [kafka-request-handler-1] (ReplicaManager.scala:229) - Error on broker 0 while processing LeaderAndIsr request correlationId 1 received from controller 0 epoch 4 for partition (robert_v_2x0,0)
java.util.NoSuchElementException: key not found: \tmp\kafka0-logs
{2013-05-10 00:03:42,689} ERROR [kafka-request-handler-0] (ReplicaManager.scala:229) - Error on broker 0 while processing LeaderAndIsr request correlationId 0 received from controller 1 epoch 5 for partition (robert_v_2x0,0)
java.util.NoSuchElementException: key not found: \tmp\kafka0-logs
{2013-05-10 00:03:57,937} DEBUG [kafka-processor-9092-1] (Logging.scala:51) - Closing connection from /192.168.1.100:52261
java.lang.reflect.InvocationTargetException
Caused by: kafka.common.FailedToSendMessageException: Failed to send messages after 3 tries.
{2013-05-09 23:52:14,347} INFO [ZkClient-EventThread-35-localhost:2181] (Logging.scala:67) - [Controller 1]: New topic creation callback for [robert_v_2x0,0]
{2013-05-09 23:52:14,349} DEBUG [kafka-request-handler-1] (Logging.scala:51) - replicas = List(0), in sync replicas = List(), leader = None
{2013-05-09 23:52:14,358} DEBUG [kafka-request-handler-1] (Logging.scala:59) - Error while fetching metadata for partition [robert_v_2x0,0]
kafka.common.LeaderNotAvailableException: No leader exists for partition 0
at kafka.admin.AdminUtils$$anonfun$3.apply(AdminUtils.scala:122)
at kafka.admin.AdminUtils$$anonfun$3.apply(AdminUtils.scala:104)
at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:206)
at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:206)
at scala.collection.LinearSeqOptimized$class.foreach(LinearSeqOptimized.scala:61)
at scala.collection.immutable.List.foreach(List.scala:45)
at scala.collection.TraversableLike$class.map(TraversableLike.scala:206)
at scala.collection.immutable.List.map(List.scala:45)
at kafka.admin.AdminUtils$.kafka$admin$AdminUtils$$fetchTopicMetadataFromZk(AdminUtils.scala:104)
at kafka.admin.AdminUtils$.fetchTopicMetadataFromZk(AdminUtils.scala:93)
at kafka.server.KafkaApis$$anonfun$handleTopicMetadataRequest$1.apply(KafkaApis.scala:417)
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)
{2013-05-09 23:52:14,579} INFO [local-vat] (Logging.scala:67) - Disconnecting from localhost:9092
{2013-05-09 23:52:14,593} INFO [kafka-processor-9092-1] (Logging.scala:67) - Closing socket connection to /127.0.0.1.
{2013-05-09 23:52:14,598} DEBUG [local-vat] (Logging.scala:51) - Successfully fetched metadata for 1 topic(s) Set(robert_v_2x0)
{2013-05-09 23:52:14,613} WARN [local-vat] (Logging.scala:82) - Error while fetching metadata partition 0 leader: none replicas: isr: isUnderReplicated: false for topic partition [robert_v_2x0,0]: [class kafka.common.LeaderNotAvailableException]
{2013-05-09 23:52:14,626} DEBUG [kafka-processor-9092-1] (Logging.scala:51) - Closing connection from /127.0.0.1:52087
{2013-05-09 23:52:14,628} DEBUG [local-vat] (Logging.scala:51) - Getting broker partition info for topic robert_v_2x0
{2013-05-09 23:52:14,636} DEBUG [local-vat] (Logging.scala:51) - Partition [robert_v_2x0,0] does not have a leader yet
{2013-05-09 23:52:14,675} INFO [ZkClient-EventThread-35-localhost:2181] (Logging.scala:67) - [Replica state machine on controller 1]: Invoking state change to NewReplica for replicas PartitionAndReplica(robert_v_2x0,0,0)
{2013-05-09 23:52:14,682} DEBUG [local-vat] (Logging.scala:51) - Broker partitions registered for topic: robert_v_2x0 are 0
{2013-05-09 23:52:14,718} DEBUG [local-vat] (Logging.scala:51) - Sending 1 messages with no compression to [robert_v_2x0,0]
{2013-05-09 23:52:14,751} WARN [local-vat] (Logging.scala:82) - Failed to send data since partitions [robert_v_2x0,0] don't have a leader
{2013-05-09 23:52:14,756} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0001 type:getDate cxid:0x27 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:14,757} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0001 type:getDate cxid:0x27 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:14,759} DEBUG [Thread-2-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0001, packet:: clientPath:null serverPath:null finished:false header:: 39,4 replyHeader:: 39,22,-101 request:: '/brokers/topics/robert_v_2x0/partitions/0/state,F response::
{2013-05-09 23:52:14,762} INFO [ZkClient-EventThread-35-localhost:2181] (Logging.scala:67) - [Partition state machine on Controller 1]: Invoking state change to OnlinePartition for partitions [robert_v_2x0,0]
{2013-05-09 23:52:14,769} DEBUG [ZkClient-EventThread-35-localhost:2181] (Logging.scala:51) - [Partition state machine on Controller 1]: Initializing leader and isr for partition [robert_v_2x0,0]
{2013-05-09 23:52:14,774} DEBUG [ZkClient-EventThread-35-localhost:2181] (Logging.scala:51) - [Partition state machine on Controller 1]: Live assigned replicas for partition [robert_v_2x0,0] are: [List(0)]
{2013-05-09 23:52:14,871} INFO [local-vat] (Logging.scala:67) - Fetching metadata with correlation id 2 for 1 topic(s) Set(robert_v_2x0)
{2013-05-09 23:52:14,903} 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-09 23:52:14,904} INFO [local-vat] (Logging.scala:67) - Connected to localhost:9092 for producing
{2013-05-09 23:52:14,910} DEBUG [ZkClient-EventThread-35-localhost:2181] (ZkEventThread.java:79) - Delivering event #6 done
{2013-05-09 23:52:14,910} DEBUG [ZkClient-EventThread-35-localhost:2181] (ZkEventThread.java:69) - Delivering event #7 ZkEvent[Children of /brokers/topics/robert_v_2x0 changed sent to kafka.controller.PartitionStateMachine$PartitionChangeListener@2e3bc634]
{2013-05-09 23:52:14,914} 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-09 23:52:14,915} DEBUG [kafka-processor-9092-0] (Logging.scala:51) - Processor 0 listening to new connection from /127.0.0.1:52090
{2013-05-09 23:52:14,929} DEBUG [kafka-request-handler-0] (Logging.scala:51) - [Kafka Request Handler 0 on Broker 0], handles request Request(0,sun.nio.ch.SelectionKeyImpl@76803c7f,null,1368165134916,/127.0.0.1:52090)
{2013-05-09 23:52:14,939} DEBUG [kafka-request-handler-1] (Logging.scala:51) - [Kafka Request Handler 1 on Broker 0], handles request Request(0,sun.nio.ch.SelectionKeyImpl@641c8053,null,1368165134926,/192.168.1.100:52076)
{2013-05-09 23:52:14,948} INFO [kafka-request-handler-1] (Logging.scala:67) - [Replica Manager on Broker 0]: Handling LeaderAndIsr request Name:LeaderAndIsrRequest;Version:0;Controller:1;ControllerEpoch:1;CorrelationId:5;ClientId:id_1-host_null-port_9093;AckTimeoutMs:1000 ms;PartitionState:(robert_v_2x0,0) -> (LeaderAndIsrInfo:(Leader:0,ISR:0,LeaderEpoch:0,ControllerEpoch:1),ReplicationFactor:1);Leaders:id:0,host:192.168.1.100,port:9092
{2013-05-09 23:52:15,096} DEBUG [kafka-request-handler-0] (Logging.scala:51) - Partition map for /brokers/topics/robert_v_2x0 is Map(0 -> List(0))
{2013-05-09 23:52:15,108} DEBUG [kafka-request-handler-1] (Logging.scala:51) - Creating or reloading log segment C:\tmp\kafka0-logs\robert_v_2x0-0\00000000000000000000.log
{2013-05-09 23:52:15,215} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:getDate cxid:0x1d zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:15,216} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDate cxid:0x1d zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:15,220} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 29,4 replyHeader:: 29,27,0 request:: '/brokers/topics/robert_v_2x0/partitions/0/state,F response:: #7b2022636f6e74726f6c6c65725f65706f6368223a312c2022697372223a5b2030205d2c20226c6561646572223a302c20226c65616465725f65706f6368223a302c202276657273696f6e223a31207d,s{27,27,1368165134834,1368165134834,0,0,0,0,80,0,27}
{2013-05-09 23:52:15,238} DEBUG [kafka-request-handler-1] (Logging.scala:51) - Loaded index file C:\tmp\kafka0-logs\robert_v_2x0-0\00000000000000000000.index with maxEntries = 1310720, maxIndexSize = 10485760, entries = 0, lastOffset = 0, file position = 0
{2013-05-09 23:52:15,362} INFO [kafka-request-handler-1] (Logging.scala:67) - [Kafka Log on Broker 0], Completed load of log robert_v_2x0-0 with log end offset 0
{2013-05-09 23:52:15,368} INFO [kafka-request-handler-1] (Logging.scala:67) - [Log Manager on Broker 0] Created log for partition [robert_v_2x0,0] in C:\tmp\kafka0-logs.
{2013-05-09 23:52:15,369} ERROR [kafka-request-handler-1] (ReplicaManager.scala:229) - Error on broker 0 while processing LeaderAndIsr request correlationId 5 received from controller 1 epoch 1 for partition (robert_v_2x0,0)
java.util.NoSuchElementException: key not found: \tmp\kafka0-logs
at scala.collection.MapLike$class.default(MapLike.scala:223)
at scala.collection.immutable.Map$Map1.default(Map.scala:93)
at scala.collection.MapLike$class.apply(MapLike.scala:134)
at scala.collection.immutable.Map$Map1.apply(Map.scala:93)
at kafka.cluster.Partition.getOrCreateReplica(Partition.scala:83)
at kafka.cluster.Partition$$anonfun$1.apply(Partition.scala:149)
at kafka.cluster.Partition$$anonfun$1.apply(Partition.scala:149)
at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:206)
at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:206)
at scala.collection.LinearSeqOptimized$class.foreach(LinearSeqOptimized.scala:61)
at scala.collection.immutable.List.foreach(List.scala:45)
at scala.collection.TraversableLike$class.map(TraversableLike.scala:206)
at scala.collection.immutable.List.map(List.scala:45)
at kafka.cluster.Partition.makeLeader(Partition.scala:149)
at kafka.server.ReplicaManager.kafka$server$ReplicaManager$$makeLeader(ReplicaManager.scala:256)
at kafka.server.ReplicaManager$$anonfun$becomeLeaderOrFollower$3.apply(ReplicaManager.scala:220)
at kafka.server.ReplicaManager$$anonfun$becomeLeaderOrFollower$3.apply(ReplicaManager.scala:212)
at scala.collection.immutable.Map$Map1.foreach(Map.scala:105)
at kafka.server.ReplicaManager.becomeLeaderOrFollower(ReplicaManager.scala:212)
at kafka.server.KafkaApis.handleLeaderAndIsrRequest(KafkaApis.scala:79)
at kafka.server.KafkaApis.handle(KafkaApis.scala:64)
at kafka.server.KafkaRequestHandler.run(KafkaRequestHandler.scala:41)
at java.lang.Thread.run(Thread.java:722)
{2013-05-09 23:52:15,379} INFO [kafka-request-handler-1] (Logging.scala:67) - [Replica Manager on Broker 0]: Handled leader and isr request Name:LeaderAndIsrRequest;Version:0;Controller:1;ControllerEpoch:1;CorrelationId:5;ClientId:id_1-host_null-port_9093;AckTimeoutMs:1000 ms;PartitionState:(robert_v_2x0,0) -> (LeaderAndIsrInfo:(Leader:0,ISR:0,LeaderEpoch:0,ControllerEpoch:1),ReplicationFactor:1);Leaders:id:0,host:192.168.1.100,port:9092
{2013-05-09 23:52:15,428} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:getDate cxid:0x1e zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:15,430} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDate cxid:0x1e zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:15,433} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 30,4 replyHeader:: 30,27,0 request:: '/brokers/topics/robert_v_2x0/partitions/0/state,F response:: #7b2022636f6e74726f6c6c65725f65706f6368223a312c2022697372223a5b2030205d2c20226c6561646572223a302c20226c65616465725f65706f6368223a302c202276657273696f6e223a31207d,s{27,27,1368165134834,1368165134834,0,0,0,0,80,0,27}
{2013-05-09 23:52:15,471} DEBUG [kafka-request-handler-0] (Logging.scala:51) - replicas = List(0), in sync replicas = List(0), leader = Some(0)
{2013-05-09 23:52:15,485} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:getDate cxid:0x1f zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/ids/0
{2013-05-09 23:52:15,486} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDate cxid:0x1f zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/ids/0
{2013-05-09 23:52:15,530} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 31,4 replyHeader:: 31,27,0 request:: '/brokers/ids/0,F response:: #7b2022686f7374223a223139322e3136382e312e313030222c20226a6d785f706f7274223a2d312c2022706f7274223a393039322c202276657273696f6e223a31207d,s{12,12,1368165113768,1368165113768,0,0,0,89664068720001024,67,0,12}
{2013-05-09 23:52:15,580} INFO [local-vat] (Logging.scala:67) - Disconnecting from localhost:9092
{2013-05-09 23:52:15,581} DEBUG [local-vat] (Logging.scala:51) - Successfully fetched metadata for 1 topic(s) Set(robert_v_2x0)
{2013-05-09 23:52:15,583} DEBUG [local-vat] (Logging.scala:51) - Getting broker partition info for topic robert_v_2x0
{2013-05-09 23:52:15,588} DEBUG [local-vat] (Logging.scala:51) - Partition [robert_v_2x0,0] has leader 0
{2013-05-09 23:52:15,589} DEBUG [local-vat] (Logging.scala:51) - Broker partitions registered for topic: robert_v_2x0 are 0
{2013-05-09 23:52:15,590} DEBUG [local-vat] (Logging.scala:51) - Sending 1 messages with no compression to [robert_v_2x0,0]
{2013-05-09 23:52:15,594} DEBUG [local-vat] (Logging.scala:51) - Producer sending messages with correlation id 4 for topics [robert_v_2x0,0] to broker 0 on 192.168.1.100:9092
{2013-05-09 23:52:15,605} INFO [kafka-processor-9092-0] (Logging.scala:67) - Closing socket connection to /127.0.0.1.
{2013-05-09 23:52:15,605} DEBUG [kafka-processor-9092-0] (Logging.scala:51) - Closing connection from /127.0.0.1:52090
{2013-05-09 23:52:15,625} 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-09 23:52:15,626} INFO [local-vat] (Logging.scala:67) - Connected to 192.168.1.100:9092 for producing
{2013-05-09 23:52:15,628} DEBUG [kafka-acceptor] (Logging.scala:51) - Accepted connection from /192.168.1.100 on /192.168.1.100:9092. sendBufferSize [actual|requested]: [1048576|1048576] recvBufferSize [actual|requested]: [1048576|1048576]
{2013-05-09 23:52:15,629} DEBUG [kafka-processor-9092-1] (Logging.scala:51) - Processor 1 listening to new connection from /192.168.1.100:52093
{2013-05-09 23:52:15,644} DEBUG [kafka-request-handler-1] (Logging.scala:51) - [Kafka Request Handler 1 on Broker 0], handles request Request(1,sun.nio.ch.SelectionKeyImpl@49ecee7a,null,1368165135630,/192.168.1.100:52093)
{2013-05-09 23:52:15,658} WARN [kafka-request-handler-1] (Logging.scala:82) - [KafkaApi-0] Produce request: Leader not local for partition [robert_v_2x0,0] on broker 0
{2013-05-09 23:52:15,662} DEBUG [kafka-request-handler-1] (Logging.scala:51) - [KafkaApi-0] Produce to local log in 17 ms
{2013-05-09 23:52:15,723} DEBUG [local-vat] (Logging.scala:51) - Producer sent messages with correlation id 4 for topics [robert_v_2x0,0] to broker 0 on 192.168.1.100:9092
{2013-05-09 23:52:15,732} ERROR [local-vat] (Logging.scala:96) - Produce request with correlation id 4 failed due to response ProducerResponse(4,Map([robert_v_2x0,0] -> ProducerResponseStatus(6,-1))). List of failed topic partitions is [robert_v_2x0,0]
{2013-05-09 23:52:15,737} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0002 type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-09 23:52:15,739} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0002 type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-09 23:52:15,742} DEBUG [main-SendThread(localhost:2181)] (ClientCnxn.java:758) - Got ping response for sessionid: 0x13e8cfed52c0002 after 48ms
{2013-05-09 23:52:15,782} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0003 type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-09 23:52:15,784} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0003 type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-09 23:52:15,787} DEBUG [main-SendThread(localhost:2181)] (ClientCnxn.java:758) - Got ping response for sessionid: 0x13e8cfed52c0003 after 6ms
{2013-05-09 23:52:15,834} INFO [local-vat] (Logging.scala:67) - Fetching metadata with correlation id 5 for 1 topic(s) Set(robert_v_2x0)
{2013-05-09 23:52:15,838} 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-09 23:52:15,839} INFO [local-vat] (Logging.scala:67) - Connected to localhost:9092 for producing
{2013-05-09 23:52:15,838} 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-09 23:52:15,842} DEBUG [kafka-processor-9092-0] (Logging.scala:51) - Processor 0 listening to new connection from /127.0.0.1:52094
{2013-05-09 23:52:15,844} DEBUG [kafka-request-handler-0] (Logging.scala:51) - [Kafka Request Handler 0 on Broker 0], handles request Request(0,sun.nio.ch.SelectionKeyImpl@5d47865a,null,1368165135843,/127.0.0.1:52094)
{2013-05-09 23:52:15,847} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:exists cxid:0x20 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0
{2013-05-09 23:52:15,848} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:exists cxid:0x20 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0
{2013-05-09 23:52:15,851} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 32,3 replyHeader:: 32,27,0 request:: '/brokers/topics/robert_v_2x0,F response:: s{22,22,1368165134125,1368165134125,0,1,0,0,43,1,25}
{2013-05-09 23:52:15,855} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:getDate cxid:0x21 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0
{2013-05-09 23:52:15,855} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDate cxid:0x21 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0
{2013-05-09 23:52:15,859} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 33,4 replyHeader:: 33,27,0 request:: '/brokers/topics/robert_v_2x0,F response:: #7b2022706172746974696f6e73223a7b202230223a5b2030205d207d2c202276657273696f6e223a31207d,s{22,22,1368165134125,1368165134125,0,1,0,0,43,1,25}
{2013-05-09 23:52:15,884} DEBUG [kafka-request-handler-0] (Logging.scala:51) - Partition map for /brokers/topics/robert_v_2x0 is Map(0 -> List(0))
{2013-05-09 23:52:15,888} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:getDate cxid:0x22 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:15,889} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDate cxid:0x22 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:15,897} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 34,4 replyHeader:: 34,27,0 request:: '/brokers/topics/robert_v_2x0/partitions/0/state,F response:: #7b2022636f6e74726f6c6c65725f65706f6368223a312c2022697372223a5b2030205d2c20226c6561646572223a302c20226c65616465725f65706f6368223a302c202276657273696f6e223a31207d,s{27,27,1368165134834,1368165134834,0,0,0,0,80,0,27}
{2013-05-09 23:52:15,945} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:getDate cxid:0x23 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:15,946} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDate cxid:0x23 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:15,949} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 35,4 replyHeader:: 35,27,0 request:: '/brokers/topics/robert_v_2x0/partitions/0/state,F response:: #7b2022636f6e74726f6c6c65725f65706f6368223a312c2022697372223a5b2030205d2c20226c6561646572223a302c20226c65616465725f65706f6368223a302c202276657273696f6e223a31207d,s{27,27,1368165134834,1368165134834,0,0,0,0,80,0,27}
{2013-05-09 23:52:15,974} DEBUG [kafka-request-handler-0] (Logging.scala:51) - replicas = List(0), in sync replicas = List(0), leader = Some(0)
{2013-05-09 23:52:16,043} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:getDate cxid:0x24 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/ids/0
{2013-05-09 23:52:16,043} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDate cxid:0x24 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/ids/0
{2013-05-09 23:52:16,047} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 36,4 replyHeader:: 36,27,0 request:: '/brokers/ids/0,F response:: #7b2022686f7374223a223139322e3136382e312e313030222c20226a6d785f706f7274223a2d312c2022706f7274223a393039322c202276657273696f6e223a31207d,s{12,12,1368165113768,1368165113768,0,0,0,89664068720001024,67,0,12}
{2013-05-09 23:52:16,074} INFO [local-vat] (Logging.scala:67) - Disconnecting from localhost:9092
{2013-05-09 23:52:16,076} DEBUG [local-vat] (Logging.scala:51) - Successfully fetched metadata for 1 topic(s) Set(robert_v_2x0)
{2013-05-09 23:52:16,076} INFO [kafka-processor-9092-0] (Logging.scala:67) - Closing socket connection to /127.0.0.1.
{2013-05-09 23:52:16,077} DEBUG [kafka-processor-9092-0] (Logging.scala:51) - Closing connection from /127.0.0.1:52094
{2013-05-09 23:52:16,076} INFO [local-vat] (Logging.scala:67) - Disconnecting from 192.168.1.100:9092
{2013-05-09 23:52:16,080} DEBUG [local-vat] (Logging.scala:51) - Getting broker partition info for topic robert_v_2x0
{2013-05-09 23:52:16,081} DEBUG [local-vat] (Logging.scala:51) - Partition [robert_v_2x0,0] has leader 0
{2013-05-09 23:52:16,082} DEBUG [local-vat] (Logging.scala:51) - Broker partitions registered for topic: robert_v_2x0 are 0
{2013-05-09 23:52:16,087} DEBUG [local-vat] (Logging.scala:51) - Sending 1 messages with no compression to [robert_v_2x0,0]
{2013-05-09 23:52:16,087} INFO [kafka-processor-9092-1] (Logging.scala:67) - Closing socket connection to /192.168.1.100.
{2013-05-09 23:52:16,089} DEBUG [kafka-processor-9092-1] (Logging.scala:51) - Closing connection from /192.168.1.100:52093
{2013-05-09 23:52:16,089} DEBUG [local-vat] (Logging.scala:51) - Producer sending messages with correlation id 7 for topics [robert_v_2x0,0] to broker 0 on 192.168.1.100:9092
{2013-05-09 23:52:16,094} 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-09 23:52:16,095} INFO [local-vat] (Logging.scala:67) - Connected to 192.168.1.100:9092 for producing
{2013-05-09 23:52:16,099} DEBUG [kafka-acceptor] (Logging.scala:51) - Accepted connection from /192.168.1.100 on /192.168.1.100:9092. sendBufferSize [actual|requested]: [1048576|1048576] recvBufferSize [actual|requested]: [1048576|1048576]
{2013-05-09 23:52:16,100} DEBUG [kafka-processor-9092-1] (Logging.scala:51) - Processor 1 listening to new connection from /192.168.1.100:52095
{2013-05-09 23:52:16,102} DEBUG [kafka-request-handler-1] (Logging.scala:51) - [Kafka Request Handler 1 on Broker 0], handles request Request(1,sun.nio.ch.SelectionKeyImpl@34729ba6,null,1368165136101,/192.168.1.100:52095)
{2013-05-09 23:52:16,106} WARN [kafka-request-handler-1] (Logging.scala:82) - [KafkaApi-0] Produce request: Leader not local for partition [robert_v_2x0,0] on broker 0
{2013-05-09 23:52:16,107} DEBUG [kafka-request-handler-1] (Logging.scala:51) - [KafkaApi-0] Produce to local log in 4 ms
{2013-05-09 23:52:16,112} DEBUG [local-vat] (Logging.scala:51) - Producer sent messages with correlation id 7 for topics [robert_v_2x0,0] to broker 0 on 192.168.1.100:9092
{2013-05-09 23:52:16,114} ERROR [local-vat] (Logging.scala:96) - Produce request with correlation id 7 failed due to response ProducerResponse(7,Map([robert_v_2x0,0] -> ProducerResponseStatus(6,-1))). List of failed topic partitions is [robert_v_2x0,0]
{2013-05-09 23:52:16,218} INFO [local-vat] (Logging.scala:67) - Fetching metadata with correlation id 8 for 1 topic(s) Set(robert_v_2x0)
{2013-05-09 23:52:16,221} 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-09 23:52:16,223} INFO [local-vat] (Logging.scala:67) - Connected to localhost:9092 for producing
{2013-05-09 23:52:16,230} 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-09 23:52:16,231} DEBUG [kafka-processor-9092-0] (Logging.scala:51) - Processor 0 listening to new connection from /127.0.0.1:52096
{2013-05-09 23:52:16,232} DEBUG [kafka-request-handler-0] (Logging.scala:51) - [Kafka Request Handler 0 on Broker 0], handles request Request(0,sun.nio.ch.SelectionKeyImpl@5ad23e7d,null,1368165136232,/127.0.0.1:52096)
{2013-05-09 23:52:16,237} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:exists cxid:0x25 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0
{2013-05-09 23:52:16,237} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:exists cxid:0x25 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0
{2013-05-09 23:52:16,244} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 37,3 replyHeader:: 37,27,0 request:: '/brokers/topics/robert_v_2x0,F response:: s{22,22,1368165134125,1368165134125,0,1,0,0,43,1,25}
{2013-05-09 23:52:16,246} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:getDate cxid:0x26 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0
{2013-05-09 23:52:16,247} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDate cxid:0x26 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0
{2013-05-09 23:52:16,250} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 38,4 replyHeader:: 38,27,0 request:: '/brokers/topics/robert_v_2x0,F response:: #7b2022706172746974696f6e73223a7b202230223a5b2030205d207d2c202276657273696f6e223a31207d,s{22,22,1368165134125,1368165134125,0,1,0,0,43,1,25}
{2013-05-09 23:52:16,262} DEBUG [kafka-request-handler-0] (Logging.scala:51) - Partition map for /brokers/topics/robert_v_2x0 is Map(0 -> List(0))
{2013-05-09 23:52:16,276} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:getDate cxid:0x27 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:16,276} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDate cxid:0x27 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:16,279} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 39,4 replyHeader:: 39,27,0 request:: '/brokers/topics/robert_v_2x0/partitions/0/state,F response:: #7b2022636f6e74726f6c6c65725f65706f6368223a312c2022697372223a5b2030205d2c20226c6561646572223a302c20226c65616465725f65706f6368223a302c202276657273696f6e223a31207d,s{27,27,1368165134834,1368165134834,0,0,0,0,80,0,27}
{2013-05-09 23:52:16,338} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:getDate cxid:0x28 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:16,339} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDate cxid:0x28 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:16,348} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 40,4 replyHeader:: 40,27,0 request:: '/brokers/topics/robert_v_2x0/partitions/0/state,F response:: #7b2022636f6e74726f6c6c65725f65706f6368223a312c2022697372223a5b2030205d2c20226c6561646572223a302c20226c65616465725f65706f6368223a302c202276657273696f6e223a31207d,s{27,27,1368165134834,1368165134834,0,0,0,0,80,0,27}
{2013-05-09 23:52:16,374} DEBUG [kafka-request-handler-0] (Logging.scala:51) - replicas = List(0), in sync replicas = List(0), leader = Some(0)
{2013-05-09 23:52:16,434} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:getDate cxid:0x29 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/ids/0
{2013-05-09 23:52:16,436} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDate cxid:0x29 zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/ids/0
{2013-05-09 23:52:16,439} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 41,4 replyHeader:: 41,27,0 request:: '/brokers/ids/0,F response:: #7b2022686f7374223a223139322e3136382e312e313030222c20226a6d785f706f7274223a2d312c2022706f7274223a393039322c202276657273696f6e223a31207d,s{12,12,1368165113768,1368165113768,0,0,0,89664068720001024,67,0,12}
{2013-05-09 23:52:16,542} INFO [local-vat] (Logging.scala:67) - Disconnecting from localhost:9092
{2013-05-09 23:52:16,545} DEBUG [local-vat] (Logging.scala:51) - Successfully fetched metadata for 1 topic(s) Set(robert_v_2x0)
{2013-05-09 23:52:16,546} INFO [local-vat] (Logging.scala:67) - Disconnecting from 192.168.1.100:9092
{2013-05-09 23:52:16,547} DEBUG [local-vat] (Logging.scala:51) - Getting broker partition info for topic robert_v_2x0
{2013-05-09 23:52:16,548} DEBUG [local-vat] (Logging.scala:51) - Partition [robert_v_2x0,0] has leader 0
{2013-05-09 23:52:16,549} DEBUG [local-vat] (Logging.scala:51) - Broker partitions registered for topic: robert_v_2x0 are 0
{2013-05-09 23:52:16,554} DEBUG [local-vat] (Logging.scala:51) - Sending 1 messages with no compression to [robert_v_2x0,0]
{2013-05-09 23:52:16,556} DEBUG [local-vat] (Logging.scala:51) - Producer sending messages with correlation id 10 for topics [robert_v_2x0,0] to broker 0 on 192.168.1.100:9092
{2013-05-09 23:52:16,559} 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-09 23:52:16,561} DEBUG [kafka-acceptor] (Logging.scala:51) - Accepted connection from /192.168.1.100 on /192.168.1.100:9092. sendBufferSize [actual|requested]: [1048576|1048576] recvBufferSize [actual|requested]: [1048576|1048576]
{2013-05-09 23:52:16,559} INFO [kafka-processor-9092-0] (Logging.scala:67) - Closing socket connection to /127.0.0.1.
{2013-05-09 23:52:16,563} DEBUG [kafka-processor-9092-0] (Logging.scala:51) - Closing connection from /127.0.0.1:52096
{2013-05-09 23:52:16,560} INFO [kafka-processor-9092-1] (Logging.scala:67) - Closing socket connection to /192.168.1.100.
{2013-05-09 23:52:16,564} DEBUG [kafka-processor-9092-1] (Logging.scala:51) - Closing connection from /192.168.1.100:52095
{2013-05-09 23:52:16,565} DEBUG [kafka-processor-9092-1] (Logging.scala:51) - Processor 1 listening to new connection from /192.168.1.100:52097
{2013-05-09 23:52:16,605} DEBUG [kafka-logflusher-1] (Logging.scala:51) - [Log Manager on Broker 1] Checking for dirty logs to flush...
{2013-05-09 23:52:16,561} INFO [local-vat] (Logging.scala:67) - Connected to 192.168.1.100:9092 for producing
{2013-05-09 23:52:16,616} DEBUG [kafka-request-handler-1] (Logging.scala:51) - [Kafka Request Handler 1 on Broker 0], handles request Request(1,sun.nio.ch.SelectionKeyImpl@e2df60d,null,1368165136615,/192.168.1.100:52097)
{2013-05-09 23:52:16,617} WARN [kafka-request-handler-1] (Logging.scala:82) - [KafkaApi-0] Produce request: Leader not local for partition [robert_v_2x0,0] on broker 0
{2013-05-09 23:52:16,618} DEBUG [kafka-request-handler-1] (Logging.scala:51) - [KafkaApi-0] Produce to local log in 1 ms
{2013-05-09 23:52:16,675} DEBUG [local-vat] (Logging.scala:51) - Producer sent messages with correlation id 10 for topics [robert_v_2x0,0] to broker 0 on 192.168.1.100:9092
{2013-05-09 23:52:16,676} ERROR [local-vat] (Logging.scala:96) - Produce request with correlation id 10 failed due to response ProducerResponse(10,Map([robert_v_2x0,0] -> ProducerResponseStatus(6,-1))). List of failed topic partitions is [robert_v_2x0,0]
{2013-05-09 23:52:16,722} DEBUG [kafka-logflusher-1] (Logging.scala:51) - [Log Manager on Broker 0] Checking for dirty logs to flush...
{2013-05-09 23:52:16,724} DEBUG [kafka-logflusher-1] (Logging.scala:51) - [Log Manager on Broker 0] robert_v_2x0 flush interval 1000 last flushed 1368165135034 time since last flush: 1688
{2013-05-09 23:52:16,778} INFO [local-vat] (Logging.scala:67) - Fetching metadata with correlation id 11 for 1 topic(s) Set(robert_v_2x0)
{2013-05-09 23:52:16,782} 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-09 23:52:16,783} DEBUG [kafka-processor-9092-0] (Logging.scala:51) - Processor 0 listening to new connection from /127.0.0.1:52098
{2013-05-09 23:52:16,784} 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-09 23:52:16,785} INFO [local-vat] (Logging.scala:67) - Connected to localhost:9092 for producing
{2013-05-09 23:52:16,787} DEBUG [kafka-request-handler-0] (Logging.scala:51) - [Kafka Request Handler 0 on Broker 0], handles request Request(0,sun.nio.ch.SelectionKeyImpl@a973465,null,1368165136786,/127.0.0.1:52098)
{2013-05-09 23:52:16,790} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:exists cxid:0x2a zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0
{2013-05-09 23:52:16,790} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:exists cxid:0x2a zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0
{2013-05-09 23:52:16,793} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 42,3 replyHeader:: 42,27,0 request:: '/brokers/topics/robert_v_2x0,F response:: s{22,22,1368165134125,1368165134125,0,1,0,0,43,1,25}
{2013-05-09 23:52:16,799} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:getDate cxid:0x2b zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0
{2013-05-09 23:52:16,799} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDate cxid:0x2b zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0
{2013-05-09 23:52:16,802} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 43,4 replyHeader:: 43,27,0 request:: '/brokers/topics/robert_v_2x0,F response:: #7b2022706172746974696f6e73223a7b202230223a5b2030205d207d2c202276657273696f6e223a31207d,s{22,22,1368165134125,1368165134125,0,1,0,0,43,1,25}
{2013-05-09 23:52:16,814} DEBUG [kafka-request-handler-0] (Logging.scala:51) - Partition map for /brokers/topics/robert_v_2x0 is Map(0 -> List(0))
{2013-05-09 23:52:16,836} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:getDate cxid:0x2c zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:16,837} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDate cxid:0x2c zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:16,842} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 44,4 replyHeader:: 44,27,0 request:: '/brokers/topics/robert_v_2x0/partitions/0/state,F response:: #7b2022636f6e74726f6c6c65725f65706f6368223a312c2022697372223a5b2030205d2c20226c6561646572223a302c20226c65616465725f65706f6368223a302c202276657273696f6e223a31207d,s{27,27,1368165134834,1368165134834,0,0,0,0,80,0,27}
{2013-05-09 23:52:16,861} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:getDate cxid:0x2d zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:16,861} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDate cxid:0x2d zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-09 23:52:16,865} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 45,4 replyHeader:: 45,27,0 request:: '/brokers/topics/robert_v_2x0/partitions/0/state,F response:: #7b2022636f6e74726f6c6c65725f65706f6368223a312c2022697372223a5b2030205d2c20226c6561646572223a302c20226c65616465725f65706f6368223a302c202276657273696f6e223a31207d,s{27,27,1368165134834,1368165134834,0,0,0,0,80,0,27}
{2013-05-09 23:52:16,892} DEBUG [kafka-request-handler-0] (Logging.scala:51) - replicas = List(0), in sync replicas = List(0), leader = Some(0)
{2013-05-09 23:52:16,962} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8cfed52c0000 type:getDate cxid:0x2e zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/ids/0
{2013-05-09 23:52:16,963} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDate cxid:0x2e zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/ids/0
{2013-05-09 23:52:16,966} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8cfed52c0000, packet:: clientPath:null serverPath:null finished:false header:: 46,4 replyHeader:: 46,27,0 request:: '/brokers/ids/0,F response:: #7b2022686f7374223a223139322e3136382e312e313030222c20226a6d785f706f7274223a2d312c2022706f7274223a393039322c202276657273696f6e223a31207d,s{12,12,1368165113768,1368165113768,0,0,0,89664068720001024,67,0,12}
{2013-05-09 23:52:16,983} INFO [local-vat] (Logging.scala:67) - Disconnecting from localhost:9092
{2013-05-09 23:52:16,984} INFO [kafka-processor-9092-0] (Logging.scala:67) - Closing socket connection to /127.0.0.1.
{2013-05-09 23:52:16,984} DEBUG [kafka-processor-9092-0] (Logging.scala:51) - Closing connection from /127.0.0.1:52098
{2013-05-09 23:52:16,985} DEBUG [local-vat] (Logging.scala:51) - Successfully fetched metadata for 1 topic(s) Set(robert_v_2x0)
{2013-05-09 23:52:16,986} INFO [local-vat] (Logging.scala:67) - Disconnecting from 192.168.1.100:9092
{2013-05-09 23:52:16,991} INFO [kafka-processor-9092-1] (Logging.scala:67) - Closing socket connection to /192.168.1.100.
{2013-05-09 23:52:16,991} DEBUG [kafka-processor-9092-1] (Logging.scala:51) - Closing connection from /192.168.1.100:52097
{2013-05-09 23:52:16,995} ERROR [local-vat] (Logging.scala:96) - Failed to send requests for topics robert_v_2x0 with correlation ids in [0,11]
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:259)
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(ScheduledThreadPoolExecutor.java:292)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:722)
Caused by: kafka.common.FailedToSendMessageException: Failed to send messages after 3 tries.
at kafka.producer.async.DefaultEventHandler.handle(DefaultEventHandler.scala:88)
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
The the second run:
{2013-05-10 00:03:39,674} DEBUG [Thread-1] (Logging.scala:51) - Partition map for /brokers/topics/robert_v_2x0 is Map(0 -> List(0))
{2013-05-10 00:03:39,683} INFO [Thread-1] (Logging.scala:67) - No state transitions triggered since no partitions are assigned to brokers 0,1
{2013-05-10 00:03:39,690} INFO [Thread-1] (Logging.scala:67) - [Replica state machine on controller 0]: Invoking state change to OnlineReplica for replicas PartitionAndReplica(robert_v_2x0,0,0)
{2013-05-10 00:03:39,967} INFO [Thread-1] (Logging.scala:67) - [Replica state machine on controller 0]: Started replica state machine with initial state -> Map((robert_v_2x0,0,0) -> OnlineReplica)
{2013-05-10 00:03:39,976} DEBUG [kafka-request-handler-0] (Logging.scala:51) - [Kafka Request Handler 0 on Broker 0], handles request Request(0,sun.nio.ch.SelectionKeyImpl@78fa5f28,null,1368165819873,/192.168.1.100:52238)
{2013-05-10 00:03:39,990} INFO [kafka-request-handler-0] (Logging.scala:67) - [Replica Manager on Broker 0]: Handling LeaderAndIsr request Name:LeaderAndIsrRequest;Version:0;Controller:0;ControllerEpoch:4;CorrelationId:0;ClientId:id_0-host_null-port_9092;AckTimeoutMs:1000 ms;PartitionState:(robert_v_2x0,0) -> (LeaderAndIsrInfo:(Leader:-1,ISR:,LeaderEpoch:1,ControllerEpoch:2),ReplicationFactor:1);Leaders:
{2013-05-10 00:03:40,021} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8d098f680000 type:getDate cxid:0x1a zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-10 00:03:40,022} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8d098f680000 type:getDate cxid:0x1a zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-10 00:03:40,025} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8d098f680000, packet:: clientPath:null serverPath:null finished:false header:: 26,4 replyHeader:: 26,52,0 request:: '/brokers/topics/robert_v_2x0/partitions/0/state,F response:: #7b2022636f6e74726f6c6c65725f65706f6368223a322c2022697372223a5b20205d2c20226c6561646572223a2d312c20226c65616465725f65706f6368223a312c202276657273696f6e223a31207d,s{27,42,1368165134834,1368165648490,1,0,0,0,80,0,27}
{2013-05-10 00:03:40,062} ERROR [kafka-request-handler-0] (ReplicaManager.scala:229) - Error on broker 0 while processing LeaderAndIsr request correlationId 0 received from controller 0 epoch 4 for partition (robert_v_2x0,0)
java.util.NoSuchElementException: key not found: \tmp\kafka0-logs
at scala.collection.MapLike$class.default(MapLike.scala:223)
at scala.collection.immutable.Map$Map1.default(Map.scala:93)
at scala.collection.MapLike$class.apply(MapLike.scala:134)
at scala.collection.immutable.Map$Map1.apply(Map.scala:93)
at kafka.cluster.Partition.getOrCreateReplica(Partition.scala:83)
at kafka.cluster.Partition.makeFollower(Partition.scala:187)
at kafka.server.ReplicaManager.kafka$server$ReplicaManager$$makeFollower(ReplicaManager.scala:273)
at kafka.server.ReplicaManager$$anonfun$becomeLeaderOrFollower$3.apply(ReplicaManager.scala:222)
at kafka.server.ReplicaManager$$anonfun$becomeLeaderOrFollower$3.apply(ReplicaManager.scala:212)
at scala.collection.immutable.Map$Map1.foreach(Map.scala:105)
at kafka.server.ReplicaManager.becomeLeaderOrFollower(ReplicaManager.scala:212)
at kafka.server.KafkaApis.handleLeaderAndIsrRequest(KafkaApis.scala:79)
at kafka.server.KafkaApis.handle(KafkaApis.scala:64)
at kafka.server.KafkaRequestHandler.run(KafkaRequestHandler.scala:41)
at java.lang.Thread.run(Thread.java:722)
{2013-05-10 00:03:40,078} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8d098f680001 type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-10 00:03:40,124} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8d098f680001 type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
{2013-05-10 00:03:40,126} DEBUG [Thread-2-SendThread(localhost:2181)] (ClientCnxn.java:758) - Got ping response for sessionid: 0x13e8d098f680001 after 71ms
{2013-05-10 00:03:40,124} DEBUG [Thread-1] (Logging.scala:51) - Leader -1, Epoch 1, Isr List(), Zk path version 1 for partition [robert_v_2x0,0]
{2013-05-10 00:03:40,142} INFO [kafka-request-handler-0] (Logging.scala:67) - [Replica Manager on Broker 0]: Handled leader and isr request Name:LeaderAndIsrRequest;Version:0;Controller:0;ControllerEpoch:4;CorrelationId:0;ClientId:id_0-host_null-port_9092;AckTimeoutMs:1000 ms;PartitionState:(robert_v_2x0,0) -> (LeaderAndIsrInfo:(Leader:-1,ISR:,LeaderEpoch:1,ControllerEpoch:2),ReplicationFactor:1);Leaders:
{2013-05-10 00:03:40,228} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8d098f680000 type:getDate cxid:0x1b zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-10 00:03:40,228} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8d098f680000 type:getDate cxid:0x1b zxid:0xfffffffffffffffe txntype:unknown reqpath:/brokers/topics/robert_v_2x0/partitions/0/state
{2013-05-10 00:03:40,231} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8d098f680000, packet:: clientPath:null serverPath:null finished:false header:: 27,4 replyHeader:: 27,52,0 request:: '/brokers/topics/robert_v_2x0/partitions/0/state,F response:: #7b2022636f6e74726f6c6c65725f65706f6368223a322c2022697372223a5b20205d2c20226c6561646572223a2d312c20226c65616465725f65706f6368223a312c202276657273696f6e223a31207d,s{27,42,1368165134834,1368165648490,1,0,0,0,80,0,27}
{2013-05-10 00:03:40,267} DEBUG [Thread-1] (Logging.scala:51) - Leader -1, Epoch 1, Isr List(), Zk path version 1 for partition [robert_v_2x0,0]
{2013-05-10 00:03:40,281} DEBUG [Thread-1] (Logging.scala:51) - [OfflinePartitionLeaderSelector]: No broker in ISR is alive for [robert_v_2x0,0]. Pick the leader from the alive assigned replicas: 0
{2013-05-10 00:03:40,284} WARN [Thread-1] (Logging.scala:82) - [OfflinePartitionLeaderSelector]: No broker in ISR is alive for [robert_v_2x0,0]. Elect leader from broker 0. There's potential data loss.
{2013-05-10 00:03:40,290} INFO [Thread-1] (Logging.scala:67) - [OfflinePartitionLeaderSelector]: Selected new leader and ISR { "ISR":"0", "leader":"0", "leaderEpoch":"2" } for offline partition [robert_v_2x0,0]
{2013-05-10 00:03:40,303} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8d098f680000 type:setData cxid:0x1c zxid:0x35 txntype:5 reqpath:n/a
{2013-05-10 00:03:40,305} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8d098f680000 type:setData cxid:0x1c zxid:0x35 txntype:5 reqpath:n/a
{2013-05-10 00:03:40,308} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8d098f680000, packet:: clientPath:null serverPath:null finished:false header:: 28,5 replyHeader:: 28,53,0 request:: '/brokers/topics/robert_v_2x0/partitions/0/state,#7b2022636f6e74726f6c6c65725f65706f6368223a342c2022697372223a5b2030205d2c20226c6561646572223a302c20226c65616465725f65706f6368223a322c202276657273696f6e223a31207d,1 response:: s{27,53,1368165134834,1368165820300,2,0,0,0,80,0,27}
{2013-05-10 00:03:40,312} DEBUG [Thread-1] (Logging.scala:51) - Conditional update of path /brokers/topics/robert_v_2x0/partitions/0/state with value { "controller_epoch":4, "isr":[ 0 ], "leader":0, "leader_epoch":2, "version":1 } and expected version 1 succeeded, returning the new version: 2
{2013-05-10 00:03:40,317} DEBUG [Thread-1] (Logging.scala:51) - [Partition state machine on Controller 0]: After leader election, leader cache is updated to Map([robert_v_2x0,0] -> (Leader:0,ISR:0,LeaderEpoch:2,ControllerEpoch:4))
{2013-05-10 00:03:40,322} INFO [Thread-1] (Logging.scala:67) - [Partition state machine on Controller 0]: Started partition state machine with initial state -> Map([robert_v_2x0,0] -> OnlinePartition)
{2013-05-10 00:03:40,326} INFO [Thread-1] (Logging.scala:67) - [Controller 0]: Broker 0 is ready to serve as the new controller with epoch 4
{2013-05-10 00:03:40,331} DEBUG [kafka-request-handler-1] (Logging.scala:51) - [Kafka Request Handler 1 on Broker 0], handles request Request(0,sun.nio.ch.SelectionKeyImpl@78fa5f28,null,1368165820329,/192.168.1.100:52238)
{2013-05-10 00:03:40,333} INFO [kafka-request-handler-1] (Logging.scala:67) - [Replica Manager on Broker 0]: Handling LeaderAndIsr request Name:LeaderAndIsrRequest;Version:0;Controller:0;ControllerEpoch:4;CorrelationId:1;ClientId:id_0-host_null-port_9092;AckTimeoutMs:1000 ms;PartitionState:(robert_v_2x0,0) -> (LeaderAndIsrInfo:(Leader:0,ISR:0,LeaderEpoch:2,ControllerEpoch:4),ReplicationFactor:1);Leaders:id:0,host:192.168.1.100,port:9092
{2013-05-10 00:03:40,337} INFO [kafka-request-handler-1] (Logging.scala:67) - [ReplicaFetcherManager on broker 0] Removing fetcher for partition [robert_v_2x0,0]
{2013-05-10 00:03:40,341} ERROR [kafka-request-handler-1] (ReplicaManager.scala:229) - Error on broker 0 while processing LeaderAndIsr request correlationId 1 received from controller 0 epoch 4 for partition (robert_v_2x0,0)
java.util.NoSuchElementException: key not found: \tmp\kafka0-logs
at scala.collection.MapLike$class.default(MapLike.scala:223)
at scala.collection.immutable.Map$Map1.default(Map.scala:93)
at scala.collection.MapLike$class.apply(MapLike.scala:134)
at scala.collection.immutable.Map$Map1.apply(Map.scala:93)
at kafka.cluster.Partition.getOrCreateReplica(Partition.scala:83)
at kafka.cluster.Partition$$anonfun$1.apply(Partition.scala:149)
at kafka.cluster.Partition$$anonfun$1.apply(Partition.scala:149)
at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:206)
at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:206)
at scala.collection.LinearSeqOptimized$class.foreach(LinearSeqOptimized.scala:61)
at scala.collection.immutable.List.foreach(List.scala:45)
at scala.collection.TraversableLike$class.map(TraversableLike.scala:206)
at scala.collection.immutable.List.map(List.scala:45)
at kafka.cluster.Partition.makeLeader(Partition.scala:149)
at kafka.server.ReplicaManager.kafka$server$ReplicaManager$$makeLeader(ReplicaManager.scala:256)
at kafka.server.ReplicaManager$$anonfun$becomeLeaderOrFollower$3.apply(ReplicaManager.scala:220)
at kafka.server.ReplicaManager$$anonfun$becomeLeaderOrFollower$3.apply(ReplicaManager.scala:212)
at scala.collection.immutable.Map$Map1.foreach(Map.scala:105)
at kafka.server.ReplicaManager.becomeLeaderOrFollower(ReplicaManager.scala:212)
at kafka.server.KafkaApis.handleLeaderAndIsrRequest(KafkaApis.scala:79)
at kafka.server.KafkaApis.handle(KafkaApis.scala:64)
at kafka.server.KafkaRequestHandler.run(KafkaRequestHandler.scala:41)
at java.lang.Thread.run(Thread.java:722)
{2013-05-10 00:03:40,369} INFO [kafka-request-handler-1] (Logging.scala:67) - [Replica Manager on Broker 0]: Handled leader and isr request Name:LeaderAndIsrRequest;Version:0;Controller:0;ControllerEpoch:4;CorrelationId:1;ClientId:id_0-host_null-port_9092;AckTimeoutMs:1000 ms;PartitionState:(robert_v_2x0,0) -> (LeaderAndIsrInfo:(Leader:0,ISR:0,LeaderEpoch:2,ControllerEpoch:4),ReplicationFactor:1);Leaders:id:0,host:192.168.1.100,port:9092
{2013-05-10 00:03:40,390} DEBUG [SyncThread:0] (FinalRequestProcessor.java:78) - Processing request:: sessionid:0x13e8d098f680000 type:getDate cxid:0x1d zxid:0xfffffffffffffffe txntype:unknown reqpath:/admin/reassign_partitions
{2013-05-10 00:03:40,390} DEBUG [SyncThread:0] (FinalRequestProcessor.java:160) - sessionid:0x13e8d098f680000 type:getDate cxid:0x1d zxid:0xfffffffffffffffe txntype:unknown reqpath:/admin/reassign_partitions
{2013-05-10 00:03:40,393} DEBUG [Thread-1-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8d098f680000, packet:: clientPath:null serverPath:null finished:false header:: 29,4 replyHeader:: 29,53,-101 request:: '/admin/reassign_partitions,T response::
{2013-05-10 00:03:40,402} INFO [Thread-1] (Logging.scala:67) - [Controller 0]: Partitions being reassigned: Map()
{2013-05-10 00:03:40,404} INFO [Thread-1] (Logging.scala:67) - [Controller 0]: Partitions already reassigned: List()
{2013-05-10 00:03:40,407} INFO [Thread-1] (Logging.scala:67) - [Controller 0]: Resuming reassignment of partitions: Map()
{2013-05-10 00:03:42,687} INFO [kafka-request-handler-0] (Logging.scala:67) - [Replica Manager on Broker 0]: Handling LeaderAndIsr request Name:LeaderAndIsrRequest;Version:0;Controller:1;ControllerEpoch:5;CorrelationId:0;ClientId:id_1-host_null-port_9093;AckTimeoutMs:1000 ms;PartitionState:(robert_v_2x0,0) -> (LeaderAndIsrInfo:(Leader:0,ISR:0,LeaderEpoch:2,ControllerEpoch:4),ReplicationFactor:1);Leaders:id:0,host:192.168.1.100,port:9092
{2013-05-10 00:03:42,688} INFO [kafka-request-handler-0] (Logging.scala:67) - [ReplicaFetcherManager on broker 0] Removing fetcher for partition [robert_v_2x0,0]
{2013-05-10 00:03:42,689} DEBUG [Thread-2-SendThread(localhost:2181)] (ClientCnxn.java:838) - Reading reply sessionid:0x13e8d098f680001, packet:: clientPath:null serverPath:null finished:false header:: 33,4 replyHeader:: 33,61,0 request:: '/brokers/topics/robert_v_2x0/partitions/0/state,F response:: #7b2022636f6e74726f6c6c65725f65706f6368223a342c2022697372223a5b2030205d2c20226c6561646572223a302c20226c65616465725f65706f6368223a322c202276657273696f6e223a31207d,s{27,53,1368165134834,1368165820300,2,0,0,0,80,0,27}
{2013-05-10 00:03:42,689} ERROR [kafka-request-handler-0] (ReplicaManager.scala:229) - Error on broker 0 while processing LeaderAndIsr request correlationId 0 received from controller 1 epoch 5 for partition (robert_v_2x0,0)
java.util.NoSuchElementException: key not found: \tmp\kafka0-logs
at scala.collection.MapLike$class.default(MapLike.scala:223)
at scala.collection.immutable.Map$Map1.default(Map.scala:93)
at scala.collection.MapLike$class.apply(MapLike.scala:134)
at scala.collection.immutable.Map$Map1.apply(Map.scala:93)
at kafka.cluster.Partition.getOrCreateReplica(Partition.scala:83)
at kafka.cluster.Partition$$anonfun$1.apply(Partition.scala:149)
at kafka.cluster.Partition$$anonfun$1.apply(Partition.scala:149)
at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:206)
at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:206)
at scala.collection.LinearSeqOptimized$class.foreach(LinearSeqOptimized.scala:61)
at scala.collection.immutable.List.foreach(List.scala:45)
at scala.collection.TraversableLike$class.map(TraversableLike.scala:206)
at scala.collection.immutable.List.map(List.scala:45)
at kafka.cluster.Partition.makeLeader(Partition.scala:149)
at kafka.server.ReplicaManager.kafka$server$ReplicaManager$$makeLeader(ReplicaManager.scala:256)
at kafka.server.ReplicaManager$$anonfun$becomeLeaderOrFollower$3.apply(ReplicaManager.scala:220)
at kafka.server.ReplicaManager$$anonfun$becomeLeaderOrFollower$3.apply(ReplicaManager.scala:212)
at scala.collection.immutable.Map$Map1.foreach(Map.scala:105)
at kafka.server.ReplicaManager.becomeLeaderOrFollower(ReplicaManager.scala:212)
at kafka.server.KafkaApis.handleLeaderAndIsrRequest(KafkaApis.scala:79)
at kafka.server.KafkaApis.handle(KafkaApis.scala:64)
at kafka.server.KafkaRequestHandler.run(KafkaRequestHandler.scala:41)
at java.lang.Thread.run(Thread.java:722)
{2013-05-10 00:03:42,699} INFO [kafka-request-handler-0] (Logging.scala:67) - [Replica Manager on Broker 0]: Handled leader and isr request Name:LeaderAndIsrRequest;Version:0;Controller:1;ControllerEpoch:5;CorrelationId:0;ClientId:id_1-host_null-port_9093;AckTimeoutMs:1000 ms;PartitionState:(robert_v_2x0,0) -> (LeaderAndIsrInfo:(Leader:0,ISR:0,LeaderEpoch:2,ControllerEpoch:4),ReplicationFactor:1);Leaders:id:0,host:192.168.1.100,port:9092
{2013-05-10 00:03:42,720} DEBUG [ZkClient-EventThread-34-localhost:2181] (Logging.scala:51) - Leader 0, Epoch 2, Isr List(0), Zk path version 2 for partition [robert_v_2x0,0]
{2013-05-10 00:03:42,724} INFO [ZkClient-EventThread-34-localhost:2181] (Logging.scala:67) - [Partition state machine on Controller 1]: Started partition state machine with initial state -> Map([robert_v_2x0,0] -> OnlinePartition)
{2013-05-10 00:03:42,725} INFO [ZkClient-EventThread-34-localhost:2181] (Logging.scala:67) - [Controller 1]: Broker 1 is ready to serve as the new controller with epoch 5
{2013-05-10 00:03:57,701} DEBUG [local-vat] (Logging.scala:51) - Broker partitions registered for topic: robert_v_2x0 are 0
{2013-05-10 00:03:57,702} DEBUG [local-vat] (Logging.scala:51) - Sending 1 messages with no compression to [robert_v_2x0,0]
{2013-05-10 00:03:57,703} DEBUG [local-vat] (Logging.scala:51) - Producer sending messages with correlation id 11 for topics [robert_v_2x0,0] to broker 0 on 192.168.1.100:9092
{2013-05-10 00:03:57,704} INFO [kafka-processor-9092-0] (Logging.scala:67) - Closing socket connection to /127.0.0.1.
{2013-05-10 00:03:57,705} DEBUG [kafka-processor-9092-0] (Logging.scala:51) - Closing connection from /127.0.0.1:52260
{2013-05-10 00:03:57,706} INFO [kafka-processor-9092-1] (Logging.scala:67) - Closing socket connection to /192.168.1.100.
{2013-05-10 00:03:57,707} DEBUG [kafka-processor-9092-1] (Logging.scala:51) - Closing connection from /192.168.1.100:52259
{2013-05-10 00:03:57,707} 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-10 00:03:57,708} INFO [local-vat] (Logging.scala:67) - Connected to 192.168.1.100:9092 for producing
{2013-05-10 00:03:57,711} DEBUG [kafka-acceptor] (Logging.scala:51) - Accepted connection from /192.168.1.100 on /192.168.1.100:9092. sendBufferSize [actual|requested]: [1048576|1048576] recvBufferSize [actual|requested]: [1048576|1048576]
{2013-05-10 00:03:57,712} DEBUG [kafka-processor-9092-1] (Logging.scala:51) - Processor 1 listening to new connection from /192.168.1.100:52261
{2013-05-10 00:03:57,714} DEBUG [kafka-request-handler-0] (Logging.scala:51) - [Kafka Request Handler 0 on Broker 0], handles request Request(1,sun.nio.ch.SelectionKeyImpl@6d92df62,null,1368165837713,/192.168.1.100:52261)
{2013-05-10 00:03:57,715} WARN [kafka-request-handler-0] (Logging.scala:82) - [KafkaApi-0] Produce request: Leader not local for partition [robert_v_2x0,0] on broker 0
{2013-05-10 00:03:57,716} DEBUG [kafka-request-handler-0] (Logging.scala:51) - [KafkaApi-0] Produce to local log in 1 ms
{2013-05-10 00:03:57,729} DEBUG [local-vat] (Logging.scala:51) - Producer sent messages with correlation id 11 for topics [robert_v_2x0,0] to broker 0 on 192.168.1.100:9092
{2013-05-10 00:03:57,731} ERROR [local-vat] (Logging.scala:96) - Produce request with correlation id 11 failed due to response ProducerResponse(11,Map([robert_v_2x0,0] -> ProducerResponseStatus(6,-1))). List of failed topic partitions is [robert_v_2x0,0]
{2013-05-10 00:03:57,832} INFO [local-vat] (Logging.scala:67) - Fetching metadata with correlation id 12 for 1 topic(s) Set(robert_v_2x0)
{2013-05-10 00:03:57,835} 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-10 00:03:57,838} DEBUG [kafka-processor-9092-0] (Logging.scala:51) - Processor 0 listening to new connection from /127.0.0.1:52262
{2013-05-10 00:03:57,839} 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-10 00:03:57,839} INFO [local-vat] (Logging.scala:67) - Connected to localhost:9092 for producing
{2013-05-10 00:03:57,911} INFO [local-vat] (Logging.scala:67) - Disconnecting from localhost:9092
{2013-05-10 00:03:57,913} DEBUG [local-vat] (Logging.scala:51) - Successfully fetched metadata for 1 topic(s) Set(robert_v_2x0)
{2013-05-10 00:03:57,913} INFO [local-vat] (Logging.scala:67) - Disconnecting from 192.168.1.100:9092
{2013-05-10 00:03:57,919} ERROR [local-vat] (Logging.scala:96) - Failed to send requests for topics robert_v_2x0 with correlation ids in [0,12]
{2013-05-10 00:03:57,935} INFO [kafka-processor-9092-0] (Logging.scala:67) - Closing socket connection to /127.0.0.1.
{2013-05-10 00:03:57,935} DEBUG [kafka-processor-9092-0] (Logging.scala:51) - Closing connection from /127.0.0.1:52262
{2013-05-10 00:03:57,937} INFO [kafka-processor-9092-1] (Logging.scala:67) - Closing socket connection to /192.168.1.100.
{2013-05-10 00:03:57,937} DEBUG [kafka-processor-9092-1] (Logging.scala:51) - Closing connection from /192.168.1.100:52261
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:259)
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(ScheduledThreadPoolExecutor.java:292)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:722)
Caused by: kafka.common.FailedToSendMessageException: Failed to send messages after 3 tries.
at kafka.producer.async.DefaultEventHandler.handle(DefaultEventHandler.scala:88)
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
thanks,
rob
|