From users-return-4348-apmail-kafka-users-archive=kafka.apache.org@kafka.apache.org Fri May 10 16:54:17 2013 Return-Path: X-Original-To: apmail-kafka-users-archive@www.apache.org Delivered-To: apmail-kafka-users-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id D5EEF11656 for ; Fri, 10 May 2013 16:54:17 +0000 (UTC) Received: (qmail 41858 invoked by uid 500); 10 May 2013 16:54:17 -0000 Delivered-To: apmail-kafka-users-archive@kafka.apache.org Received: (qmail 41833 invoked by uid 500); 10 May 2013 16:54:17 -0000 Mailing-List: contact users-help@kafka.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: users@kafka.apache.org Delivered-To: mailing list users@kafka.apache.org Received: (qmail 41821 invoked by uid 99); 10 May 2013 16:54:17 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 10 May 2013 16:54:17 +0000 X-ASF-Spam-Status: No, hits=-0.7 required=5.0 tests=RCVD_IN_DNSWL_LOW,SPF_HELO_PASS,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of Robert.Withers@dish.com designates 204.76.128.104 as permitted sender) Received: from [204.76.128.104] (HELO dishnetwork.com) (204.76.128.104) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 10 May 2013 16:54:12 +0000 X-TM-IMSS-Message-ID:<640fb98c0004c86c@dishnetwork.com> Received: from MER2-EXCHHUBA1.echostar.com ([10.3.81.18]) by dishnetwork.com ([10.3.122.28]) with ESMTP (TREND IMSS SMTP Service 7.1) id 640fb98c0004c86c ; Fri, 10 May 2013 10:53:51 -0600 Received: from MER2-EXCHNEW07.echostar.com ([10.3.106.41]) by MER2-EXCHHUBA1.echostar.com ([10.3.81.18]) with mapi; Fri, 10 May 2013 10:53:51 -0600 From: "Withers, Robert" To: "'users@kafka.apache.org'" Date: Fri, 10 May 2013 10:53:50 -0600 Subject: RE: [0.8] exception running on windows when attempting to send to an uncreated topic Thread-Topic: [0.8] exception running on windows when attempting to send to an uncreated topic Thread-Index: Ac5NlzC8lOpF3kI9SzmajCRNDfg1iAAAEnbgAAHL04A= Message-ID: <774701A9FC7AD345BBB943C3F96A637ED0B2EDC82E@MER2-EXCHNEW07.echostar.com> References: <774701A9FC7AD345BBB943C3F96A637ED0B2EDC82D@MER2-EXCHNEW07.echostar.com> In-Reply-To: <774701A9FC7AD345BBB943C3F96A637ED0B2EDC82D@MER2-EXCHNEW07.echostar.com> Accept-Language: en-US Content-Language: en-US X-MS-Has-Attach: X-MS-TNEF-Correlator: acceptlanguage: en-US Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable MIME-Version: 1.0 X-Virus-Checked: Checked by ClamAV on apache.org I thought about this further...all props files should be the same between p= latforms. Therefore, it seems it is a kafka issue to read/write with a win= dows filesystem, with forward slash properties. Thanks, rob -----Original Message----- From: Withers, Robert Sent: Friday, May 10, 2013 10:01 AM To: users@kafka.apache.org Subject: RE: [0.8] exception running on windows when attempting to send to = an uncreated topic Ahh, I missed that. However, I am using the forward slash in the log.dir s= etting 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 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 th= e > 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 partitio= n > 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 f= or > 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 f= or > 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 f= or > 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 f= or > 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 =3D List(0), in sync replicas =3D List(), l= eader > =3D 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.sca= la:206) > at > scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.sca= la:206) > at > scala.collection.LinearSeqOptimized$class.foreach(LinearSeqOptimized.scal= a: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(KafkaA= pis.scala:417) > at > kafka.server.KafkaApis$$anonfun$handleTopicMetadataRequest$1.apply(KafkaA= pis.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) - Partitio= n > [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 t= o > 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:0xfffffffffffffff= e > 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:getDa= te > 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 =3D 1500 (requested 1500), SO_RCVBUF =3D 8192 (req= uested > -1), SO_SNDBUF =3D 102400 (requested 102400). > {2013-05-09 23:52:14,904} INFO [local-vat] (Logging.scala:67) - Connecte= d > 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 reque= st > 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 reque= st > 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;Correla= tionId: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),Replic= ationFactor: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:0xfffffffffffffff= e > 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:getDa= te > 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:: > #7b2022636f6e74726f6c6c65725f65706f6368223a312c2022697372223a5b2030205d2c= 20226c6561646572223a302c20226c65616465725f65706f6368223a302c202276657273696= f6e223a31207d,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 =3D 1310720, maxIndexSize =3D 10485760, entries =3D 0, lastOff= set =3D 0, > file position =3D 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 f= or > 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.sca= la:206) > at > scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.sca= la:206) > at > scala.collection.LinearSeqOptimized$class.foreach(LinearSeqOptimized.scal= a: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(Repli= caManager.scala:256) > at > kafka.server.ReplicaManager$$anonfun$becomeLeaderOrFollower$3.apply(Repli= caManager.scala:220) > at > kafka.server.ReplicaManager$$anonfun$becomeLeaderOrFollower$3.apply(Repli= caManager.scala:212) > at scala.collection.immutable.Map$Map1.foreach(Map.scala:105) > at > kafka.server.ReplicaManager.becomeLeaderOrFollower(ReplicaManager.scala:2= 12) > at kafka.server.KafkaApis.handleLeaderAndIsrRequest(KafkaApis.scala:7= 9) > 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 is= r > request > Name:LeaderAndIsrRequest;Version:0;Controller:1;ControllerEpoch:1;Correla= tionId: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),Replic= ationFactor: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:0xfffffffffffffff= e > 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:getDa= te > 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:: > #7b2022636f6e74726f6c6c65725f65706f6368223a312c2022697372223a5b2030205d2c= 20226c6561646572223a302c20226c65616465725f65706f6368223a302c202276657273696= f6e223a31207d,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 =3D List(0), in sync replicas =3D List(0), = leader > =3D Some(0) > {2013-05-09 23:52:15,485} DEBUG [SyncThread:0] > (FinalRequestProcessor.java:78) - Processing request:: > sessionid:0x13e8cfed52c0000 type:getDate cxid:0x1f zxid:0xfffffffffffffff= e > txntype:unknown reqpath:/brokers/ids/0 > {2013-05-09 23:52:15,486} DEBUG [SyncThread:0] > (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDa= te > 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:: > #7b2022686f7374223a223139322e3136382e312e313030222c20226a6d785f706f727422= 3a2d312c2022706f7274223a393039322c202276657273696f6e223a31207d,s{12,12,1368= 165113768,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) - Partitio= n > [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 =3D 1500 (requested 1500), SO_RCVBUF =3D 8192 (req= uested > -1), SO_SNDBUF =3D 102400 (requested 102400). > {2013-05-09 23:52:15,626} INFO [local-vat] (Logging.scala:67) - Connecte= d > 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 reque= st > 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: 0x13e8cfed52c000= 2 > 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: 0x13e8cfed52c000= 3 > 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 =3D 1500 (requested 1500), SO_RCVBUF =3D 8192 (req= uested > -1), SO_SNDBUF =3D 102400 (requested 102400). > {2013-05-09 23:52:15,839} INFO [local-vat] (Logging.scala:67) - Connecte= d > 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 reque= st > 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:exist= s > 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:0xfffffffffffffff= e > txntype:unknown reqpath:/brokers/topics/robert_v_2x0 > {2013-05-09 23:52:15,855} DEBUG [SyncThread:0] > (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDa= te > 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:: > #7b2022706172746974696f6e73223a7b202230223a5b2030205d207d2c20227665727369= 6f6e223a31207d,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:0xfffffffffffffff= e > 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:getDa= te > 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:: > #7b2022636f6e74726f6c6c65725f65706f6368223a312c2022697372223a5b2030205d2c= 20226c6561646572223a302c20226c65616465725f65706f6368223a302c202276657273696= f6e223a31207d,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:0xfffffffffffffff= e > 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:getDa= te > 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:: > #7b2022636f6e74726f6c6c65725f65706f6368223a312c2022697372223a5b2030205d2c= 20226c6561646572223a302c20226c65616465725f65706f6368223a302c202276657273696= f6e223a31207d,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 =3D List(0), in sync replicas =3D List(0), = leader > =3D Some(0) > {2013-05-09 23:52:16,043} DEBUG [SyncThread:0] > (FinalRequestProcessor.java:78) - Processing request:: > sessionid:0x13e8cfed52c0000 type:getDate cxid:0x24 zxid:0xfffffffffffffff= e > txntype:unknown reqpath:/brokers/ids/0 > {2013-05-09 23:52:16,043} DEBUG [SyncThread:0] > (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDa= te > 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:: > #7b2022686f7374223a223139322e3136382e312e313030222c20226a6d785f706f727422= 3a2d312c2022706f7274223a393039322c202276657273696f6e223a31207d,s{12,12,1368= 165113768,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) - Partitio= n > [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 =3D 1500 (requested 1500), SO_RCVBUF =3D 8192 (req= uested > -1), SO_SNDBUF =3D 102400 (requested 102400). > {2013-05-09 23:52:16,095} INFO [local-vat] (Logging.scala:67) - Connecte= d > 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 reque= st > 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 =3D 1500 (requested 1500), SO_RCVBUF =3D 8192 (req= uested > -1), SO_SNDBUF =3D 102400 (requested 102400). > {2013-05-09 23:52:16,223} INFO [local-vat] (Logging.scala:67) - Connecte= d > 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 reque= st > 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:exist= s > 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:0xfffffffffffffff= e > txntype:unknown reqpath:/brokers/topics/robert_v_2x0 > {2013-05-09 23:52:16,247} DEBUG [SyncThread:0] > (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDa= te > 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:: > #7b2022706172746974696f6e73223a7b202230223a5b2030205d207d2c20227665727369= 6f6e223a31207d,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:0xfffffffffffffff= e > 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:getDa= te > 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:: > #7b2022636f6e74726f6c6c65725f65706f6368223a312c2022697372223a5b2030205d2c= 20226c6561646572223a302c20226c65616465725f65706f6368223a302c202276657273696= f6e223a31207d,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:0xfffffffffffffff= e > 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:getDa= te > 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:: > #7b2022636f6e74726f6c6c65725f65706f6368223a312c2022697372223a5b2030205d2c= 20226c6561646572223a302c20226c65616465725f65706f6368223a302c202276657273696= f6e223a31207d,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 =3D List(0), in sync replicas =3D List(0), = leader > =3D Some(0) > {2013-05-09 23:52:16,434} DEBUG [SyncThread:0] > (FinalRequestProcessor.java:78) - Processing request:: > sessionid:0x13e8cfed52c0000 type:getDate cxid:0x29 zxid:0xfffffffffffffff= e > txntype:unknown reqpath:/brokers/ids/0 > {2013-05-09 23:52:16,436} DEBUG [SyncThread:0] > (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDa= te > 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:: > #7b2022686f7374223a223139322e3136382e312e313030222c20226a6d785f706f727422= 3a2d312c2022706f7274223a393039322c202276657273696f6e223a31207d,s{12,12,1368= 165113768,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) - Partitio= n > [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 =3D 1500 (requested 1500), SO_RCVBUF =3D 8192 (req= uested > -1), SO_SNDBUF =3D 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) - Connecte= d > 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 reque= st > 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 broke= r > 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 =3D 1500 (requested 1500), SO_RCVBUF =3D 8192 (req= uested > -1), SO_SNDBUF =3D 102400 (requested 102400). > {2013-05-09 23:52:16,785} INFO [local-vat] (Logging.scala:67) - Connecte= d > 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 reque= st > 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:exist= s > 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:0xfffffffffffffff= e > txntype:unknown reqpath:/brokers/topics/robert_v_2x0 > {2013-05-09 23:52:16,799} DEBUG [SyncThread:0] > (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDa= te > 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:: > #7b2022706172746974696f6e73223a7b202230223a5b2030205d207d2c20227665727369= 6f6e223a31207d,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:0xfffffffffffffff= e > 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:getDa= te > 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:: > #7b2022636f6e74726f6c6c65725f65706f6368223a312c2022697372223a5b2030205d2c= 20226c6561646572223a302c20226c65616465725f65706f6368223a302c202276657273696= f6e223a31207d,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:0xfffffffffffffff= e > 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:getDa= te > 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:: > #7b2022636f6e74726f6c6c65725f65706f6368223a312c2022697372223a5b2030205d2c= 20226c6561646572223a302c20226c65616465725f65706f6368223a302c202276657273696= f6e223a31207d,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 =3D List(0), in sync replicas =3D List(0), = leader > =3D Some(0) > {2013-05-09 23:52:16,962} DEBUG [SyncThread:0] > (FinalRequestProcessor.java:78) - Processing request:: > sessionid:0x13e8cfed52c0000 type:getDate cxid:0x2e zxid:0xfffffffffffffff= e > txntype:unknown reqpath:/brokers/ids/0 > {2013-05-09 23:52:16,963} DEBUG [SyncThread:0] > (FinalRequestProcessor.java:160) - sessionid:0x13e8cfed52c0000 type:getDa= te > 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:: > #7b2022686f7374223a223139322e3136382e312e313030222c20226a6d785f706f727422= 3a2d312c2022706f7274223a393039322c202276657273696f6e223a31207d,s{12,12,1368= 165113768,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 t= o > 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(DelegatingMethodAccessorI= mpl.java:43) > at java.lang.reflect.Method.invoke(Method.java:601) > at > org.reefedjib.murmur.lib.MessageSend$Sender.privateSendIt(MessageSend.jav= a: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.acce= ss$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.jav= a: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 fo= r > 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 initia= l > 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 reque= st > 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;Correla= tionId:0;ClientId:id_0-host_null-port_9092;AckTimeoutMs:1000 > ms;PartitionState:(robert_v_2x0,0) -> > (LeaderAndIsrInfo:(Leader:-1,ISR:,LeaderEpoch:1,ControllerEpoch:2),Replic= ationFactor:1);Leaders: > {2013-05-10 00:03:40,021} DEBUG [SyncThread:0] > (FinalRequestProcessor.java:78) - Processing request:: > sessionid:0x13e8d098f680000 type:getDate cxid:0x1a zxid:0xfffffffffffffff= e > 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:getDa= te > 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:: > #7b2022636f6e74726f6c6c65725f65706f6368223a322c2022697372223a5b20205d2c20= 226c6561646572223a2d312c20226c65616465725f65706f6368223a312c202276657273696= f6e223a31207d,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 f= or > 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(Rep= licaManager.scala:273) > at > kafka.server.ReplicaManager$$anonfun$becomeLeaderOrFollower$3.apply(Repli= caManager.scala:222) > at > kafka.server.ReplicaManager$$anonfun$becomeLeaderOrFollower$3.apply(Repli= caManager.scala:212) > at scala.collection.immutable.Map$Map1.foreach(Map.scala:105) > at > kafka.server.ReplicaManager.becomeLeaderOrFollower(ReplicaManager.scala:2= 12) > at kafka.server.KafkaApis.handleLeaderAndIsrRequest(KafkaApis.scala:7= 9) > 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: 0x13e8d098f68000= 1 > 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 is= r > request > Name:LeaderAndIsrRequest;Version:0;Controller:0;ControllerEpoch:4;Correla= tionId:0;ClientId:id_0-host_null-port_9092;AckTimeoutMs:1000 > ms;PartitionState:(robert_v_2x0,0) -> > (LeaderAndIsrInfo:(Leader:-1,ISR:,LeaderEpoch:1,ControllerEpoch:2),Replic= ationFactor:1);Leaders: > {2013-05-10 00:03:40,228} DEBUG [SyncThread:0] > (FinalRequestProcessor.java:78) - Processing request:: > sessionid:0x13e8d098f680000 type:getDate cxid:0x1b zxid:0xfffffffffffffff= e > 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:getDa= te > 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:: > #7b2022636f6e74726f6c6c65725f65706f6368223a322c2022697372223a5b20205d2c20= 226c6561646572223a2d312c20226c65616465725f65706f6368223a312c202276657273696= f6e223a31207d,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:setDa= ta > 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,#7b2022636f6e74726f6c6c6= 5725f65706f6368223a342c2022697372223a5b2030205d2c20226c6561646572223a302c20= 226c65616465725f65706f6368223a322c202276657273696f6e223a31207d,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/stat= e > with value { "controller_epoch":4, "isr":[ 0 ], "leader":0, > "leader_epoch":2, "version":1 } and expected version 1 succeeded, returni= ng > the new version: 2 > {2013-05-10 00:03:40,317} DEBUG [Thread-1] (Logging.scala:51) - [Partitio= n > 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) - [Partitio= n > 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 epo= ch > 4 > {2013-05-10 00:03:40,331} DEBUG [kafka-request-handler-1] > (Logging.scala:51) - [Kafka Request Handler 1 on Broker 0], handles reque= st > 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;Correla= tionId: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),Replic= ationFactor: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 f= or > 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.sca= la:206) > at > scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.sca= la:206) > at > scala.collection.LinearSeqOptimized$class.foreach(LinearSeqOptimized.scal= a: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(Repli= caManager.scala:256) > at > kafka.server.ReplicaManager$$anonfun$becomeLeaderOrFollower$3.apply(Repli= caManager.scala:220) > at > kafka.server.ReplicaManager$$anonfun$becomeLeaderOrFollower$3.apply(Repli= caManager.scala:212) > at scala.collection.immutable.Map$Map1.foreach(Map.scala:105) > at > kafka.server.ReplicaManager.becomeLeaderOrFollower(ReplicaManager.scala:2= 12) > at kafka.server.KafkaApis.handleLeaderAndIsrRequest(KafkaApis.scala:7= 9) > 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 is= r > request > Name:LeaderAndIsrRequest;Version:0;Controller:0;ControllerEpoch:4;Correla= tionId: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),Replic= ationFactor: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:0xfffffffffffffff= e > txntype:unknown reqpath:/admin/reassign_partitions > {2013-05-10 00:03:40,390} DEBUG [SyncThread:0] > (FinalRequestProcessor.java:160) - sessionid:0x13e8d098f680000 type:getDa= te > 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;Correla= tionId: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),Replic= ationFactor: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:: > #7b2022636f6e74726f6c6c65725f65706f6368223a342c2022697372223a5b2030205d2c= 20226c6561646572223a302c20226c65616465725f65706f6368223a322c202276657273696= f6e223a31207d,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 f= or > 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.sca= la:206) > at > scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.sca= la:206) > at > scala.collection.LinearSeqOptimized$class.foreach(LinearSeqOptimized.scal= a: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(Repli= caManager.scala:256) > at > kafka.server.ReplicaManager$$anonfun$becomeLeaderOrFollower$3.apply(Repli= caManager.scala:220) > at > kafka.server.ReplicaManager$$anonfun$becomeLeaderOrFollower$3.apply(Repli= caManager.scala:212) > at scala.collection.immutable.Map$Map1.foreach(Map.scala:105) > at > kafka.server.ReplicaManager.becomeLeaderOrFollower(ReplicaManager.scala:2= 12) > at kafka.server.KafkaApis.handleLeaderAndIsrRequest(KafkaApis.scala:7= 9) > 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 is= r > request > Name:LeaderAndIsrRequest;Version:0;Controller:1;ControllerEpoch:5;Correla= tionId: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),Replic= ationFactor: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 fo= r > 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 ne= w > 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 =3D 1500 (requested 1500), SO_RCVBUF =3D 8192 (req= uested > -1), SO_SNDBUF =3D 102400 (requested 102400). > {2013-05-10 00:03:57,708} INFO [local-vat] (Logging.scala:67) - Connecte= d > 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 reque= st > 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 broke= r > 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 =3D 1500 (requested 1500), SO_RCVBUF =3D 8192 (req= uested > -1), SO_SNDBUF =3D 102400 (requested 102400). > {2013-05-10 00:03:57,839} INFO [local-vat] (Logging.scala:67) - Connecte= d > 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 t= o > 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(DelegatingMethodAccessorI= mpl.java:43) > at java.lang.reflect.Method.invoke(Method.java:601) > at > org.reefedjib.murmur.lib.MessageSend$Sender.privateSendIt(MessageSend.jav= a: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.acce= ss$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.jav= a: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