kafka-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Rob Withers" <reefed...@gmail.com>
Subject Re: [0.8] exception running on windows when attempting to send to an uncreated topic
Date Sat, 11 May 2013 00:38:03 GMT
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)
{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)
{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)
{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] 
(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] 
(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] 
(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)



Mime
View raw message