It seems this is because we hardcoded "/" in HighwaterMarkCheckpoint. Could you file a jira?
val name = path + "/" + HighwaterMarkCheckpoint.highWatermarkFileName Thanks, Jun On Fri, May 10, 2013 at 5:38 PM, Rob Withers <reefed...@gmail.com> wrote: > Jun, thanks! I changed the properties for the broker to the following, > worked, and I was able to produce data, for a while. More on the next > issue below. > > thanks, > rob > > ...I changed the broker properties to the following: > > for broker 0: > props.setProperty("log.dir", "\\tmp\\kafka0-logs"); > for broker 1: > props.setProperty("log.dir", "\\tmp\\kafka1-logs"); > > Additionally, it seems the zookeeper had no problems with the following > property setting: > props.setProperty("dataDir", "/tmp/zookeeper"); > > > Now here is the combined log for a zookeeper, 2 brokers, a producer, and 2 > consumers. It produced for awhile, as evidenced by the log in the > beginning, and > - I have 10 MB in C:\tmp\kafka1-logs\robert_v_** > 2x0-0\00000000000000000000.**index > - I have 3.4 MB in C:\tmp\kafka1-logs\robert_v_** > 2x0-0\00000000000000000000.log > > Due to the following FATAL line, both brokers shutdown (and their > listening sockets go away), and so the producer fails: > {2013-05-10 18:23:57,689} FATAL [highwatermark-checkpoint-**thread1] > (Logging.scala:109) - Attempt to swap the new high watermark file with the > old one failed > > {2013-05-10 18:23:57,456} DEBUG [local-vat] (Logging.scala:51) - Getting > broker partition info for topic robert_v_2x0 > {2013-05-10 18:23:57,457} DEBUG [local-vat] (Logging.scala:51) - Partition > [robert_v_2x0,0] has leader 1 > {2013-05-10 18:23:57,458} DEBUG [local-vat] (Logging.scala:51) - Broker > partitions registered for topic: robert_v_2x0 are 0 > {2013-05-10 18:23:57,459} DEBUG [local-vat] (Logging.scala:51) - Sending 1 > messages with no compression to [robert_v_2x0,0] > {2013-05-10 18:23:57,461} DEBUG [local-vat] (Logging.scala:51) - Producer > sending messages with correlation id 176 for topics [robert_v_2x0,0] to > broker 1 on 192.168.1.100:9093 > {2013-05-10 18:23:57,466} DEBUG [kafka-request-handler-0] > (Logging.scala:51) - [Kafka Request Handler 0 on Broker 1], handles request > Request(1,sun.nio.ch.**SelectionKeyImpl@3d308bfd,**null,1368231837466,/ > 192.168.1.**100:56009 <http://192.168.1.100:56009>) > {2013-05-10 18:23:57,468} DEBUG [kafka-request-handler-0] > (Logging.scala:51) - Adding index entry 86 => 4281531 to > 00000000000000000000.index. > {2013-05-10 18:23:57,469} DEBUG [kafka-request-handler-0] > (Logging.scala:51) - Partition [robert_v_2x0,0] on broker 1: Highwatermark > for partition [robert_v_2x0,0] updated to 87 > {2013-05-10 18:23:57,469} DEBUG [kafka-request-handler-0] > (Logging.scala:51) - [KafkaApi-1] Produce to local log in 2 ms > {2013-05-10 18:23:57,475} DEBUG [local-vat] (Logging.scala:51) - Producer > sent messages with correlation id 176 for topics [robert_v_2x0,0] to broker > 1 on 192.168.1.100:9093 > {2013-05-10 18:23:57,497} DEBUG [local-vat] (Logging.scala:51) - Getting > broker partition info for topic robert_v_2x0 > {2013-05-10 18:23:57,634} DEBUG [local-vat] (Logging.scala:51) - Partition > [robert_v_2x0,0] has leader 1 > {2013-05-10 18:23:57,635} DEBUG [local-vat] (Logging.scala:51) - Broker > partitions registered for topic: robert_v_2x0 are 0 > {2013-05-10 18:23:57,636} DEBUG [local-vat] (Logging.scala:51) - Sending 1 > messages with no compression to [robert_v_2x0,0] > {2013-05-10 18:23:57,637} DEBUG [local-vat] (Logging.scala:51) - Producer > sending messages with correlation id 178 for topics [robert_v_2x0,0] to > broker 1 on 192.168.1.100:9093 > {2013-05-10 18:23:57,689} FATAL [highwatermark-checkpoint-**thread1] > (Logging.scala:109) - Attempt to swap the new high watermark file with the > old one failed > {2013-05-10 18:23:57,739} INFO [Thread-4] (Logging.scala:67) - [Kafka > Server 0], shutting down > {2013-05-10 18:23:57,771} DEBUG [kafka-request-handler-1] > (Logging.scala:51) - [Kafka Request Handler 1 on Broker 1], handles request > Request(1,sun.nio.ch.**SelectionKeyImpl@3d308bfd,**null,1368231837641,/ > 192.168.1.**100:56009 <http://192.168.1.100:56009>) > {2013-05-10 18:23:57,772} DEBUG [kafka-request-handler-1] > (Logging.scala:51) - Partition [robert_v_2x0,0] on broker 1: Highwatermark > for partition [robert_v_2x0,0] updated to 88 > {2013-05-10 18:23:57,773} DEBUG [kafka-request-handler-1] > (Logging.scala:51) - [KafkaApi-1] Produce to local log in 2 ms > {2013-05-10 18:23:57,785} DEBUG [local-vat] (Logging.scala:51) - Producer > sent messages with correlation id 178 for topics [robert_v_2x0,0] to broker > 1 on 192.168.1.100:9093 > {2013-05-10 18:23:57,794} DEBUG [local-vat] (Logging.scala:51) - Getting > broker partition info for topic robert_v_2x0 > {2013-05-10 18:23:57,795} DEBUG [local-vat] (Logging.scala:51) - Partition > [robert_v_2x0,0] has leader 1 > {2013-05-10 18:23:57,795} DEBUG [local-vat] (Logging.scala:51) - Broker > partitions registered for topic: robert_v_2x0 are 0 > {2013-05-10 18:23:57,796} DEBUG [local-vat] (Logging.scala:51) - Sending 1 > messages with no compression to [robert_v_2x0,0] > {2013-05-10 18:23:57,798} DEBUG [local-vat] (Logging.scala:51) - Producer > sending messages with correlation id 180 for topics [robert_v_2x0,0] to > broker 1 on 192.168.1.100:9093 > {2013-05-10 18:23:57,802} INFO [Thread-5] (Logging.scala:67) - [Kafka > Server 1], shutting down > {2013-05-10 18:23:57,803} INFO [Thread-5] (Logging.scala:67) - [Socket > Server on Broker 1], shutting down > {2013-05-10 18:23:57,806} DEBUG [kafka-acceptor] (Logging.scala:51) - > Closing server socket and selector. > {2013-05-10 18:23:57,817} DEBUG [kafka-processor-9093-0] > (Logging.scala:51) - Closing selector. > {2013-05-10 18:23:57,820} INFO [Thread-4] (Logging.scala:67) - [Socket > Server on Broker 0], shutting down > {2013-05-10 18:23:57,822} DEBUG [kafka-acceptor] (Logging.scala:51) - > Closing server socket and selector. > {2013-05-10 18:23:57,825} DEBUG [kafka-request-handler-0] > (Logging.scala:51) - [Kafka Request Handler 0 on Broker 1], handles request > Request(1,sun.nio.ch.**SelectionKeyImpl@3d308bfd,**null,1368231837814,/ > 192.168.1.**100:56009 <http://192.168.1.100:56009>) > {2013-05-10 18:23:57,826} DEBUG [kafka-processor-9092-0] > (Logging.scala:51) - Closing selector. > {2013-05-10 18:23:57,830} DEBUG [kafka-processor-9092-1] > (Logging.scala:51) - Closing selector. > {2013-05-10 18:23:57,834} DEBUG [kafka-request-handler-0] > (Logging.scala:51) - Adding index entry 88 => 4287735 to > 00000000000000000000.index. > {2013-05-10 18:23:57,835} DEBUG [kafka-request-handler-0] > (Logging.scala:51) - Partition [robert_v_2x0,0] on broker 1: Highwatermark > for partition [robert_v_2x0,0] updated to 89 > {2013-05-10 18:23:57,836} DEBUG [kafka-request-handler-0] > (Logging.scala:51) - [KafkaApi-1] Produce to local log in 11 ms > {2013-05-10 18:23:57,844} DEBUG [kafka-processor-9093-1] > (Logging.scala:51) - Closing selector. > {2013-05-10 18:23:57,849} INFO [Thread-5] (Logging.scala:67) - [Socket > Server on Broker 1], shut down completely > {2013-05-10 18:23:57,853} INFO [Thread-5] (Logging.scala:67) - [Kafka > Request Handler on Broker 1], shutting down > {2013-05-10 18:23:57,860} INFO [Thread-5] (Logging.scala:67) - [Kafka > Request Handler on Broker 1], shutted down completely > {2013-05-10 18:23:57,864} INFO [Thread-5] (Logging.scala:67) - Shutdown > Kafka scheduler > {2013-05-10 18:23:57,867} DEBUG [Thread-5] (Logging.scala:51) - > [KafkaApi-1] Shutting down. > {2013-05-10 18:23:57,869} DEBUG [Thread-5] (Logging.scala:51) - > ExpiredRequestReaper-1 Shutting down. > {2013-05-10 18:23:57,871} INFO [Thread-4] (Logging.scala:67) - [Socket > Server on Broker 0], shut down completely > {2013-05-10 18:23:57,872} INFO [Thread-4] (Logging.scala:67) - [Kafka > Request Handler on Broker 0], shutting down > {2013-05-10 18:23:57,879} INFO [Thread-4] (Logging.scala:67) - [Kafka > Request Handler on Broker 0], shutted down completely > {2013-05-10 18:23:57,883} INFO [Thread-4] (Logging.scala:67) - Shutdown > Kafka scheduler > {2013-05-10 18:23:57,883} DEBUG [Thread-4] (Logging.scala:51) - > [KafkaApi-0] Shutting down. > {2013-05-10 18:23:57,884} DEBUG [Thread-4] (Logging.scala:51) - > ExpiredRequestReaper-0 Shutting down. > {2013-05-10 18:23:57,896} DEBUG [Thread-5] (Logging.scala:51) - > ExpiredRequestReaper-1 Shut down complete. > {2013-05-10 18:23:57,896} DEBUG [Thread-4] (Logging.scala:51) - > ExpiredRequestReaper-0 Shut down complete. > {2013-05-10 18:23:57,899} DEBUG [Thread-4] (Logging.scala:51) - > ExpiredRequestReaper-0 Shutting down. > {2013-05-10 18:23:57,898} DEBUG [Thread-5] (Logging.scala:51) - > ExpiredRequestReaper-1 Shutting down. > {2013-05-10 18:23:57,906} DEBUG [Thread-5] (Logging.scala:51) - > ExpiredRequestReaper-1 Shut down complete. > {2013-05-10 18:23:57,907} DEBUG [Thread-5] (Logging.scala:51) - > [KafkaApi-1] Shut down complete. > {2013-05-10 18:23:57,913} INFO [Thread-5] (Logging.scala:67) - Closing > zookeeper client... > {2013-05-10 18:23:57,914} DEBUG [Thread-5] (ZkClient.java:915) - Closing > ZkClient... > {2013-05-10 18:23:57,916} INFO [ZkClient-EventThread-34-**localhost:2181] > (ZkEventThread.java:82) - Terminate ZkClient event thread. > {2013-05-10 18:23:57,917} DEBUG [Thread-4] (Logging.scala:51) - > ExpiredRequestReaper-0 Shut down complete. > {2013-05-10 18:23:57,917} DEBUG [Thread-5] (ZkConnection.java:77) - > Closing ZooKeeper connected to localhost:2181 > {2013-05-10 18:23:57,918} DEBUG [Thread-5] (ZooKeeper.java:527) - Closing > session: 0x13e90f70d640001 > {2013-05-10 18:23:57,917} DEBUG [Thread-4] (Logging.scala:51) - > [KafkaApi-0] Shut down complete. > {2013-05-10 18:23:57,918} DEBUG [Thread-5] (ClientCnxn.java:1287) - > Closing client for session: 0x13e90f70d640001 > {2013-05-10 18:23:57,919} INFO [Thread-4] (Logging.scala:67) - Closing > zookeeper client... > {2013-05-10 18:23:57,920} DEBUG [Thread-4] (ZkClient.java:915) - Closing > ZkClient... > {2013-05-10 18:23:57,921} INFO [ZkClient-EventThread-35-**localhost:2181] > (ZkEventThread.java:82) - Terminate ZkClient event thread. > {2013-05-10 18:23:57,922} DEBUG [Thread-4] (ZkConnection.java:77) - > Closing ZooKeeper connected to localhost:2181 > {2013-05-10 18:23:57,923} DEBUG [Thread-4] (ZooKeeper.java:527) - Closing > session: 0x13e90f70d640000 > {2013-05-10 18:23:57,923} DEBUG [Thread-4] (ClientCnxn.java:1287) - > Closing client for session: 0x13e90f70d640000 > {2013-05-10 18:23:57,922} INFO [ProcessThread:-1] > (PrepRequestProcessor.java:**387) - Processed session termination for > sessionid: 0x13e90f70d640001 > {2013-05-10 18:23:57,925} INFO [ProcessThread:-1] > (PrepRequestProcessor.java:**387) - Processed session termination for > sessionid: 0x13e90f70d640000 > {2013-05-10 18:23:57,926} DEBUG [SyncThread:0] (FinalRequestProcessor.java: > **78) - Processing request:: sessionid:0x13e90f70d640001 > type:closeSession cxid:0x2d zxid:0x1c txntype:-11 reqpath:n/a > {2013-05-10 18:23:57,928} DEBUG [Thread-2-SendThread(**localhost:2181)] > (ClientCnxn.java:782) - Got notification sessionid:0x13e90f70d640001 > {2013-05-10 18:23:57,928} DEBUG [Thread-2-SendThread(**localhost:2181)] > (ClientCnxn.java:799) - Got WatchedEvent state:SyncConnected > type:NodeChildrenChanged path:/brokers/ids for sessionid 0x13e90f70d640001 > {2013-05-10 18:23:57,929} DEBUG [Thread-2-EventThread] (ZkClient.java:351) > - Received event: WatchedEvent state:SyncConnected type:NodeChildrenChanged > path:/brokers/ids > {2013-05-10 18:23:57,929} DEBUG [SyncThread:0] (DataTree.java:816) - > Deleting ephemeral node /brokers/ids/1 for session 0x13e90f70d640001 > {2013-05-10 18:23:57,931} DEBUG [Thread-2-SendThread(**localhost:2181)] > (ClientCnxn.java:782) - Got notification sessionid:0x13e90f70d640001 > {2013-05-10 18:23:57,931} DEBUG [Thread-2-SendThread(**localhost:2181)] > (ClientCnxn.java:799) - Got WatchedEvent state:SyncConnected > type:NodeDeleted path:/controller for sessionid 0x13e90f70d640001 > {2013-05-10 18:23:57,944} DEBUG [Thread-1-SendThread(**localhost:2181)] > (ClientCnxn.java:782) - Got notification sessionid:0x13e90f70d640000 > {2013-05-10 18:23:57,944} DEBUG [Thread-1-SendThread(**localhost:2181)] > (ClientCnxn.java:799) - Got WatchedEvent state:SyncConnected > type:NodeDeleted path:/controller for sessionid 0x13e90f70d640000 > {2013-05-10 18:23:57,945} DEBUG [Thread-1-EventThread] (ZkClient.java:351) > - Received event: WatchedEvent state:SyncConnected type:NodeDeleted > path:/controller > {2013-05-10 18:23:57,945} DEBUG [SyncThread:0] (DataTree.java:816) - > Deleting ephemeral node /controller for session 0x13e90f70d640001 > {2013-05-10 18:23:57,946} DEBUG [SyncThread:0] (FinalRequestProcessor.java: > **160) - sessionid:0x13e90f70d640001 type:closeSession cxid:0x2d > zxid:0x1c txntype:-11 reqpath:n/a > {2013-05-10 18:23:57,948} DEBUG [Thread-2-SendThread(**localhost:2181)] > (ClientCnxn.java:838) - Reading reply sessionid:0x13e90f70d640001, packet:: > clientPath:null serverPath:null finished:false header:: 45,-11 > replyHeader:: 45,28,0 request:: null response:: null > {2013-05-10 18:23:57,948} DEBUG [Thread-5] (ClientCnxn.java:1271) - > Disconnecting client for session: 0x13e90f70d640001 > {2013-05-10 18:23:57,949} INFO [Thread-5] (ZooKeeper.java:538) - Session: > 0x13e90f70d640001 closed > {2013-05-10 18:23:57,950} DEBUG [Thread-5] (ZkClient.java:928) - Closing > ZkClient...done > {2013-05-10 18:23:57,952} WARN [NIOServerCxn.Factory:0.0.0.0/** > 0.0.0.0:2181 <http://0.0.0.0/0.0.0.0:2181>] (NIOServerCnxn.java:634) - > EndOfStreamException: Unable to read additional data from client sessionid > 0x13e90f70d640001, likely client has closed socket > {2013-05-10 18:23:57,953} INFO [NIOServerCxn.Factory:0.0.0.0/** > 0.0.0.0:2181 <http://0.0.0.0/0.0.0.0:2181>] (NIOServerCnxn.java:1435) - > Closed socket connection for client /127.0.0.1:55979 which had sessionid > 0x13e90f70d640001 > {2013-05-10 18:23:57,953} INFO [Thread-5] (Logging.scala:67) - [Replica > Manager on Broker 1]: Shut down > {2013-05-10 18:23:57,955} INFO [Thread-5] (Logging.scala:67) - > [ReplicaFetcherManager on broker 1] shutting down > {2013-05-10 18:23:57,956} DEBUG [SyncThread:0] (FinalRequestProcessor.java: > **78) - Processing request:: sessionid:0x13e90f70d640000 > type:closeSession cxid:0x1e zxid:0x1d txntype:-11 reqpath:n/a > {2013-05-10 18:23:57,959} DEBUG [SyncThread:0] (DataTree.java:816) - > Deleting ephemeral node /brokers/ids/0 for session 0x13e90f70d640000 > {2013-05-10 18:23:57,959} DEBUG [SyncThread:0] (FinalRequestProcessor.java: > **160) - sessionid:0x13e90f70d640000 type:closeSession cxid:0x1e > zxid:0x1d txntype:-11 reqpath:n/a > {2013-05-10 18:23:57,960} INFO [Thread-5] (Logging.scala:67) - > [ReplicaFetcherManager on broker 1] shutdown completed > {2013-05-10 18:23:57,961} DEBUG [Thread-1-SendThread(**localhost:2181)] > (ClientCnxn.java:838) - Reading reply sessionid:0x13e90f70d640000, packet:: > clientPath:null serverPath:null finished:false header:: 30,-11 > replyHeader:: 30,29,0 request:: null response:: null > {2013-05-10 18:23:57,961} DEBUG [Thread-2-EventThread] (ZkClient.java:364) > - ignoring event '{NodeChildrenChanged | /brokers/ids}' since shutdown > triggered > {2013-05-10 18:23:57,962} DEBUG [Thread-2-EventThread] (ZkClient.java:395) > - Leaving process event > {2013-05-10 18:23:57,962} DEBUG [Thread-2-EventThread] (ZkClient.java:351) > - Received event: WatchedEvent state:SyncConnected type:NodeDeleted > path:/controller > {2013-05-10 18:23:57,962} DEBUG [Thread-2-EventThread] (ZkClient.java:364) > - ignoring event '{NodeDeleted | /controller}' since shutdown triggered > {2013-05-10 18:23:57,962} DEBUG [Thread-2-EventThread] (ZkClient.java:395) > - Leaving process event > {2013-05-10 18:23:57,963} INFO [Thread-2-EventThread] > (ClientCnxn.java:520) - EventThread shut down > {2013-05-10 18:23:57,964} INFO [NIOServerCxn.Factory:0.0.0.0/** > 0.0.0.0:2181 <http://0.0.0.0/0.0.0.0:2181>] (NIOServerCnxn.java:1435) - > Closed socket connection for client /127.0.0.1:55978 which had sessionid > 0x13e90f70d640000 > {2013-05-10 18:23:57,968} DEBUG [Thread-1-SendThread(**localhost:2181)] > (ClientCnxn.java:1147) - An exception was thrown while closing send thread > for session 0x13e90f70d640000 : Unable to read additional data from server > sessionid 0x13e90f70d640000, likely server has closed socket > {2013-05-10 18:23:57,969} DEBUG [Thread-4] (ClientCnxn.java:1271) - > Disconnecting client for session: 0x13e90f70d640000 > {2013-05-10 18:23:57,970} INFO [Thread-4] (ZooKeeper.java:538) - Session: > 0x13e90f70d640000 closed > {2013-05-10 18:23:57,970} DEBUG [Thread-4] (ZkClient.java:928) - Closing > ZkClient...done > {2013-05-10 18:23:57,971} DEBUG [Thread-1-EventThread] (ZkClient.java:364) > - ignoring event '{NodeDeleted | /controller}' since shutdown triggered > {2013-05-10 18:23:57,976} DEBUG [Thread-1-EventThread] (ZkClient.java:395) > - Leaving process event > {2013-05-10 18:23:57,971} INFO [Thread-4] (Logging.scala:67) - [Replica > Manager on Broker 0]: Shut down > {2013-05-10 18:23:57,976} INFO [Thread-1-EventThread] > (ClientCnxn.java:520) - EventThread shut down > {2013-05-10 18:23:57,977} INFO [Thread-4] (Logging.scala:67) - > [ReplicaFetcherManager on broker 0] shutting down > {2013-05-10 18:23:57,980} INFO [Thread-4] (Logging.scala:67) - > [ReplicaFetcherManager on broker 0] shutdown completed > {2013-05-10 18:23:57,983} INFO [Thread-4] (Logging.scala:67) - [Replica > Manager on Broker 0]: Shutted down completely > {2013-05-10 18:23:57,987} DEBUG [Thread-4] (Logging.scala:51) - [Log > Manager on Broker 0] Shutting down. > {2013-05-10 18:23:57,999} DEBUG [Thread-4] (Logging.scala:51) - [Log > Manager on Broker 0] Shutdown complete. > {2013-05-10 18:23:58,003} INFO [Thread-4] (Logging.scala:67) - [Kafka > Server 0], shut down completed > {2013-05-10 18:23:58,357} DEBUG [SyncThread:0] (FinalRequestProcessor.java: > **78) - Processing request:: sessionid:0x13e90f70d640003 type:ping > cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a > {2013-05-10 18:23:58,358} DEBUG [SyncThread:0] (FinalRequestProcessor.java: > **160) - sessionid:0x13e90f70d640003 type:ping cxid:0xfffffffffffffffe > zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a > {2013-05-10 18:23:58,359} DEBUG [main-SendThread(localhost:**2181)] > (ClientCnxn.java:758) - Got ping response for sessionid: 0x13e90f70d640003 > after 3ms > {2013-05-10 18:23:58,791} DEBUG [SyncThread:0] (FinalRequestProcessor.java: > **78) - Processing request:: sessionid:0x13e90f70d640002 type:ping > cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a > {2013-05-10 18:23:58,792} DEBUG [SyncThread:0] (FinalRequestProcessor.java: > **160) - sessionid:0x13e90f70d640002 type:ping cxid:0xfffffffffffffffe > zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a > {2013-05-10 18:23:58,795} DEBUG [main-SendThread(localhost:**2181)] > (ClientCnxn.java:758) - Got ping response for sessionid: 0x13e90f70d640002 > after 6ms > {2013-05-10 18:23:59,300} INFO [local-vat] (Logging.scala:67) - > Disconnecting from 192.168.1.100:9093 > {2013-05-10 18:23:59,307} WARN [local-vat] (Logging.scala:88) - Failed to > send producer request with correlation id 180 to broker 1 with data for > partitions [robert_v_2x0,0] > java.net.**SocketTimeoutException > at sun.nio.ch.SocketAdaptor$**SocketInputStream.read(** > SocketAdaptor.java:226) > > >