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)