kafka-node LeaderNotAvailable errors on send

Question

I'm using kafka-node to send messages between the services in my application. I'm using the wurstmeister/kafka and wurstmeister/zookeeper containers to run Kafka and Zookeeper (for simplicity's sake).

Every time I try to send() a message to the broker, I get a LeaderNotAvailable error. I used kafka-web-console to inspect the broker, and it shows the two topics that I had set up, but it shows no leader (see http://cl.ly/image/1f3g0K2S1J0F).

Neither from reading the container logs (below), nor any documentation, nor trying to search for this problem can I work out why it's not working (or how to fix it).

Update sending seems to work if I destroy the containers and start them up again (rather than just restarting them using docker-compose up).

zookeeper_1 | JMX enabled by default
zookeeper_1 | Using config: /opt/zookeeper-3.4.6/bin/../conf/zoo.cfg
zookeeper_1 | 2015-09-01 10:44:15,108 [myid:] - INFO  [main:QuorumPeerConfig@103] - Reading configuration from: /opt/zookeeper-3.4.6/bin/../conf/zoo.cfg
zookeeper_1 | 2015-09-01 10:44:15,113 [myid:] - INFO  [main:DatadirCleanupManager@78] - autopurge.snapRetainCount set to 3
zookeeper_1 | 2015-09-01 10:44:15,113 [myid:] - INFO  [main:DatadirCleanupManager@79] - autopurge.purgeInterval set to 1
zookeeper_1 | 2015-09-01 10:44:15,119 [myid:] - WARN  [main:QuorumPeerMain@113] - Either no config or no quorum defined in config, running  in standalone mode
zookeeper_1 | 2015-09-01 10:44:15,119 [myid:] - INFO  [PurgeTask:DatadirCleanupManager$PurgeTask@138] - Purge task started.
zookeeper_1 | 2015-09-01 10:44:15,133 [myid:] - INFO  [PurgeTask:DatadirCleanupManager$PurgeTask@144] - Purge task completed.
zookeeper_1 | 2015-09-01 10:44:15,135 [myid:] - INFO  [main:QuorumPeerConfig@103] - Reading configuration from: /opt/zookeeper-3.4.6/bin/../conf/zoo.cfg
zookeeper_1 | 2015-09-01 10:44:15,135 [myid:] - INFO  [main:ZooKeeperServerMain@95] - Starting server
zookeeper_1 | 2015-09-01 10:44:15,143 [myid:] - INFO  [main:Environment@100] - Server environment:zookeeper.version=3.4.6-1569965, built on 02/20/2014 09:09 GMT
zookeeper_1 | 2015-09-01 10:44:15,143 [myid:] - INFO  [main:Environment@100] - Server environment:host.name=abd919b6a5a2
zookeeper_1 | 2015-09-01 10:44:15,144 [myid:] - INFO  [main:Environment@100] - Server environment:java.version=1.7.0_65
zookeeper_1 | 2015-09-01 10:44:15,144 [myid:] - INFO  [main:Environment@100] - Server environment:java.vendor=Oracle Corporation
zookeeper_1 | 2015-09-01 10:44:15,144 [myid:] - INFO  [main:Environment@100] - Server environment:java.home=/usr/lib/jvm/java-7-openjdk-amd64/jre
zookeeper_1 | 2015-09-01 10:44:15,144 [myid:] - INFO  [main:Environment@100] - Server environment:java.class.path=/opt/zookeeper-3.4.6/bin/../build/classes:/opt/zookeeper-3.4.6/bin/../build/lib/*.jar:/opt/zookeeper-3.4.6/bin/../lib/slf4j-log4j12-1.6.1.jar:/opt/zookeeper-3.4.6/bin/../lib/slf4j-api-1.6.1.jar:/opt/zookeeper-3.4.6/bin/../lib/netty-3.7.0.Final.jar:/opt/zookeeper-3.4.6/bin/../lib/log4j-1.2.16.jar:/opt/zookeeper-3.4.6/bin/../lib/jline-0.9.94.jar:/opt/zookeeper-3.4.6/bin/../zookeeper-3.4.6.jar:/opt/zookeeper-3.4.6/bin/../src/java/lib/*.jar:/opt/zookeeper-3.4.6/bin/../conf:
zookeeper_1 | 2015-09-01 10:44:15,144 [myid:] - INFO  [main:Environment@100] - Server environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib
zookeeper_1 | 2015-09-01 10:44:15,144 [myid:] - INFO  [main:Environment@100] - Server environment:java.io.tmpdir=/tmp
zookeeper_1 | 2015-09-01 10:44:15,146 [myid:] - INFO  [main:Environment@100] - Server environment:java.compiler=<NA>
zookeeper_1 | 2015-09-01 10:44:15,146 [myid:] - INFO  [main:Environment@100] - Server environment:os.name=Linux
zookeeper_1 | 2015-09-01 10:44:15,146 [myid:] - INFO  [main:Environment@100] - Server environment:os.arch=amd64
zookeeper_1 | 2015-09-01 10:44:15,146 [myid:] - INFO  [main:Environment@100] - Server environment:os.version=3.18.11-tinycore64
zookeeper_1 | 2015-09-01 10:44:15,147 [myid:] - INFO  [main:Environment@100] - Server environment:user.name=root
zookeeper_1 | 2015-09-01 10:44:15,147 [myid:] - INFO  [main:Environment@100] - Server environment:user.home=/root
zookeeper_1 | 2015-09-01 10:44:15,147 [myid:] - INFO  [main:Environment@100] - Server environment:user.dir=/opt/zookeeper-3.4.6
zookeeper_1 | 2015-09-01 10:44:15,148 [myid:] - INFO  [main:ZooKeeperServer@755] - tickTime set to 2000
zookeeper_1 | 2015-09-01 10:44:15,148 [myid:] - INFO  [main:ZooKeeperServer@764] - minSessionTimeout set to -1
zookeeper_1 | 2015-09-01 10:44:15,148 [myid:] - INFO  [main:ZooKeeperServer@773] - maxSessionTimeout set to -1
zookeeper_1 | 2015-09-01 10:44:15,161 [myid:] - INFO  [main:NIOServerCnxnFactory@94] - binding to port 0.0.0.0/0.0.0.0:2181
kafka_1     | [2015-09-01 10:44:16,754] INFO Verifying properties (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,782] INFO Property advertised.host.name is overridden to 192.168.59.103 (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,782] INFO Property advertised.port is overridden to 32773 (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,782] INFO Property broker.id is overridden to 32773 (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,782] INFO Property log.cleaner.enable is overridden to false (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,783] INFO Property log.dirs is overridden to /kafka/kafka-logs-32773 (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,783] INFO Property log.retention.check.interval.ms is overridden to 300000 (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,783] INFO Property log.retention.hours is overridden to 168 (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,783] INFO Property log.segment.bytes is overridden to 1073741824 (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,783] INFO Property num.io.threads is overridden to 8 (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,783] INFO Property num.network.threads is overridden to 3 (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,784] INFO Property num.partitions is overridden to 1 (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,784] INFO Property num.recovery.threads.per.data.dir is overridden to 1 (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,785] INFO Property port is overridden to 9092 (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,785] INFO Property socket.receive.buffer.bytes is overridden to 102400 (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,785] INFO Property socket.request.max.bytes is overridden to 104857600 (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,785] INFO Property socket.send.buffer.bytes is overridden to 102400 (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,785] WARN Property version is not valid (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,786] INFO Property zookeeper.connect is overridden to 172.17.0.10:2181 (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,786] INFO Property zookeeper.connection.timeout.ms is overridden to 6000 (kafka.utils.VerifiableProperties)
kafka_1     | [2015-09-01 10:44:16,817] INFO [Kafka Server 32773], starting (kafka.server.KafkaServer)
kafka_1     | [2015-09-01 10:44:16,820] INFO [Kafka Server 32773], Connecting to zookeeper on 172.17.0.10:2181 (kafka.server.KafkaServer)
kafka_1     | [2015-09-01 10:44:16,828] INFO Starting ZkClient event thread. (org.I0Itec.zkclient.ZkEventThread)
kafka_1     | [2015-09-01 10:44:16,837] INFO Client environment:zookeeper.version=3.4.6-1569965, built on 02/20/2014 09:09 GMT (org.apache.zookeeper.ZooKeeper)
kafka_1     | [2015-09-01 10:44:16,837] INFO Client environment:host.name=34ff07e953a2 (org.apache.zookeeper.ZooKeeper)
kafka_1     | [2015-09-01 10:44:16,837] INFO Client environment:java.version=1.6.0_34 (org.apache.zookeeper.ZooKeeper)
kafka_1     | [2015-09-01 10:44:16,837] INFO Client environment:java.vendor=Sun Microsystems Inc. (org.apache.zookeeper.ZooKeeper)
kafka_1     | [2015-09-01 10:44:16,837] INFO Client environment:java.home=/usr/lib/jvm/java-6-openjdk-amd64/jre (org.apache.zookeeper.ZooKeeper)
kafka_1     | [2015-09-01 10:44:16,838] INFO Client environment:java.class.path=:/opt/kafka_2.10-0.8.2.1/bin/../core/build/dependant-libs-2.10*/*.jar:/opt/kafka_2.10-0.8.2.1/bin/../examples/build/libs//kafka-examples*.jar:/opt/kafka_2.10-0.8.2.1/bin/../contrib/hadoop-consumer/build/libs//kafka-hadoop-consumer*.jar:/opt/kafka_2.10-0.8.2.1/bin/../contrib/hadoop-producer/build/libs//kafka-hadoop-producer*.jar:/opt/kafka_2.10-0.8.2.1/bin/../clients/build/libs/kafka-clients*.jar:/opt/kafka_2.10-0.8.2.1/bin/../libs/jopt-simple-3.2.jar:/opt/kafka_2.10-0.8.2.1/bin/../libs/kafka-clients-0.8.2.1.jar:/opt/kafka_2.10-0.8.2.1/bin/../libs/kafka_2.10-0.8.2.1-javadoc.jar:/opt/kafka_2.10-0.8.2.1/bin/../libs/kafka_2.10-0.8.2.1-scaladoc.jar:/opt/kafka_2.10-0.8.2.1/bin/../libs/kafka_2.10-0.8.2.1-sources.jar:/opt/kafka_2.10-0.8.2.1/bin/../libs/kafka_2.10-0.8.2.1-test.jar:/opt/kafka_2.10-0.8.2.1/bin/../libs/kafka_2.10-0.8.2.1.jar:/opt/kafka_2.10-0.8.2.1/bin/../libs/log4j-1.2.16.jar:/opt/kafka_2.10-0.8.2.1/bin/../libs/lz4-1.2.0.jar:/opt/kafka_2.10-0.8.2.1/bin/../libs/metrics-core-2.2.0.jar:/opt/kafka_2.10-0.8.2.1/bin/../libs/scala-library-2.10.4.jar:/opt/kafka_2.10-0.8.2.1/bin/../libs/slf4j-api-1.7.6.jar:/opt/kafka_2.10-0.8.2.1/bin/../libs/slf4j-log4j12-1.6.1.jar:/opt/kafka_2.10-0.8.2.1/bin/../libs/snappy-java-1.1.1.6.jar:/opt/kafka_2.10-0.8.2.1/bin/../libs/zkclient-0.3.jar:/opt/kafka_2.10-0.8.2.1/bin/../libs/zookeeper-3.4.6.jar:/opt/kafka_2.10-0.8.2.1/bin/../core/build/libs/kafka_2.10*.jar (org.apache.zookeeper.ZooKeeper)
kafka_1     | [2015-09-01 10:44:16,838] INFO Client environment:java.library.path=/usr/lib/jvm/java-6-openjdk-amd64/jre/lib/amd64/server:/usr/lib/jvm/java-6-openjdk-amd64/jre/lib/amd64:/usr/lib/jvm/java-6-openjdk-amd64/jre/../lib/amd64:/usr/java/packages/lib/amd64:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib (org.apache.zookeeper.ZooKeeper)
kafka_1     | [2015-09-01 10:44:16,838] INFO Client environment:java.io.tmpdir=/tmp (org.apache.zookeeper.ZooKeeper)
kafka_1     | [2015-09-01 10:44:16,838] INFO Client environment:java.compiler=<NA> (org.apache.zookeeper.ZooKeeper)
kafka_1     | [2015-09-01 10:44:16,838] INFO Client environment:os.name=Linux (org.apache.zookeeper.ZooKeeper)
kafka_1     | [2015-09-01 10:44:16,838] INFO Client environment:os.arch=amd64 (org.apache.zookeeper.ZooKeeper)
kafka_1     | [2015-09-01 10:44:16,838] INFO Client environment:os.version=3.18.11-tinycore64 (org.apache.zookeeper.ZooKeeper)
kafka_1     | [2015-09-01 10:44:16,838] INFO Client environment:user.name=root (org.apache.zookeeper.ZooKeeper)
kafka_1     | [2015-09-01 10:44:16,838] INFO Client environment:user.home=/root (org.apache.zookeeper.ZooKeeper)
kafka_1     | [2015-09-01 10:44:16,838] INFO Client environment:user.dir=/ (org.apache.zookeeper.ZooKeeper)
kafka_1     | [2015-09-01 10:44:16,839] INFO Initiating client connection, connectString=172.17.0.10:2181 sessionTimeout=6000 watcher=org.I0Itec.zkclient.ZkClient@4b704006 (org.apache.zookeeper.ZooKeeper)
kafka_1     | [2015-09-01 10:44:16,860] INFO Opening socket connection to server 172.17.0.10/172.17.0.10:2181. Will not attempt to authenticate using SASL (unknown error) (org.apache.zookeeper.ClientCnxn)
kafka_1     | [2015-09-01 10:44:16,865] INFO Socket connection established to 172.17.0.10/172.17.0.10:2181, initiating session (org.apache.zookeeper.ClientCnxn)
zookeeper_1 | 2015-09-01 10:44:16,866 [myid:] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket connection from /172.17.0.12:53850
zookeeper_1 | 2015-09-01 10:44:16,872 [myid:] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client attempting to establish new session at /172.17.0.12:53850
zookeeper_1 | 2015-09-01 10:44:16,873 [myid:] - INFO  [SyncThread:0:FileTxnLog@199] - Creating new log file: log.52
zookeeper_1 | 2015-09-01 10:44:16,883 [myid:] - INFO  [SyncThread:0:ZooKeeperServer@617] - Established session 0x14f8881d8da0000 with negotiated timeout 6000 for client /172.17.0.12:53850
kafka_1     | [2015-09-01 10:44:16,886] INFO Session establishment complete on server 172.17.0.10/172.17.0.10:2181, sessionid = 0x14f8881d8da0000, negotiated timeout = 6000 (org.apache.zookeeper.ClientCnxn)
kafka_1     | [2015-09-01 10:44:16,887] INFO zookeeper state changed (SyncConnected) (org.I0Itec.zkclient.ZkClient)
kafka_1     | [2015-09-01 10:44:17,030] INFO Log directory '/kafka/kafka-logs-32773' not found, creating it. (kafka.log.LogManager)
kafka_1     | [2015-09-01 10:44:17,037] INFO Loading logs. (kafka.log.LogManager)
kafka_1     | [2015-09-01 10:44:17,042] INFO Logs loading complete. (kafka.log.LogManager)
kafka_1     | [2015-09-01 10:44:17,043] INFO Starting log cleanup with a period of 300000 ms. (kafka.log.LogManager)
kafka_1     | [2015-09-01 10:44:17,047] INFO Starting log flusher with a default period of 9223372036854775807 ms. (kafka.log.LogManager)
kafka_1     | [2015-09-01 10:44:17,074] INFO Awaiting socket connections on 0.0.0.0:9092. (kafka.network.Acceptor)
kafka_1     | [2015-09-01 10:44:17,075] INFO [Socket Server on Broker 32773], Started (kafka.network.SocketServer)
kafka_1     | [2015-09-01 10:44:17,129] INFO Will not load MX4J, mx4j-tools.jar is not in the classpath (kafka.utils.Mx4jLoader$)
kafka_1     | [2015-09-01 10:44:17,162] INFO 32773 successfully elected as leader (kafka.server.ZookeeperLeaderElector)
zookeeper_1 | 2015-09-01 10:44:17,344 [myid:] - INFO  [ProcessThread(sid:0 cport:-1)::PrepRequestProcessor@645] - Got user-level KeeperException when processing sessionid:0x14f8881d8da0000 type:delete cxid:0x27 zxid:0x55 txntype:-1 reqpath:n/a Error Path:/admin/preferred_replica_election Error:KeeperErrorCode = NoNode for /admin/preferred_replica_election
kafka_1     | [2015-09-01 10:44:17,358] INFO New leader is 32773 (kafka.server.ZookeeperLeaderElector$LeaderChangeListener)
kafka_1     | [2015-09-01 10:44:17,360] INFO Registered broker 32773 at path /brokers/ids/32773 with address 192.168.59.103:32773. (kafka.utils.ZkUtils$)
kafka_1     | [2015-09-01 10:44:17,371] INFO [Kafka Server 32773], started (kafka.server.KafkaServer)
zookeeper_1 | 2015-09-01 10:49:01,422 [myid:] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket connection from /192.168.59.3:50220
zookeeper_1 | 2015-09-01 10:49:01,426 [myid:] - WARN  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@822] - Connection request from old client /192.168.59.3:50220; will be dropped if server is in r-o mode
zookeeper_1 | 2015-09-01 10:49:01,426 [myid:] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client attempting to establish new session at /192.168.59.3:50220
zookeeper_1 | 2015-09-01 10:49:01,428 [myid:] - INFO  [SyncThread:0:ZooKeeperServer@617] - Established session 0x14f8881d8da0001 with negotiated timeout 30000 for client /192.168.59.3:50220
zookeeper_1 | 2015-09-01 10:52:20,886 [myid:] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket connection from /172.17.42.1:50639
zookeeper_1 | 2015-09-01 10:52:20,890 [myid:] - WARN  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@822] - Connection request from old client /172.17.42.1:50639; will be dropped if server is in r-o mode
zookeeper_1 | 2015-09-01 10:52:20,890 [myid:] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client attempting to establish new session at /172.17.42.1:50639
zookeeper_1 | 2015-09-01 10:52:20,893 [myid:] - INFO  [SyncThread:0:ZooKeeperServer@617] - Established session 0x14f8881d8da0002 with negotiated timeout 6000 for client /172.17.42.1:50639

Answer 1

This nonsense cost me more than it should have. For anyone else that comes across this - removing the image worked for me as well. Here's some copy pasta:

    # Stop all containers
    docker stop $(docker ps -a -q)
    # Get the id of the container you want to remove, looks like: 8e8683455c7c
    docker ps -a
    # Remove it
    docker rm 8e8683455c7c 
    # Get the id of the image you want to remove, looks like: f82f62b5876b
    docker images
    # Delete image
    docker rmi f82f62b5876b
    # Pull the slot machine lever one more time
    docker-compose up

Also also - source: https://gist.github.com/JeffBelback/5687bb02f3618965ca8f