kafka-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Withers, Robert" <Robert.With...@dish.com>
Subject RE: [0.8] exception running on windows when attempting to send to an uncreated topic
Date Fri, 10 May 2013 16:01:11 GMT
Ahh, I missed that.  However, I am using the forward slash in the log.dir setting in the properties file.

Thanks,


Rob Withers
Staff Analyst/Developer
o: (720) 514-8963
c:  (571) 262-1873



-----Original Message-----
From: Jun Rao [mailto:junrao@gmail.com]
Sent: Friday, May 10, 2013 9:58 AM
To: users@kafka.apache.org
Subject: Re: [0.8] exception running on windows when attempting to send to an uncreated topic

Did you see my last comment in
https://issues.apache.org/jira/browse/KAFKA-876 ?

Thanks,

Jun


On Thu, May 9, 2013 at 11:27 PM, Rob Withers <reefedjib@gmail.com> wrote:

> 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
View raw message