kafka-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Rob Withers" <reefed...@gmail.com>
Subject Re: [0.8] exception running on windows when attempting to send to an uncreated topic
Date Fri, 10 May 2013 06:27:41 GMT
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
Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message