kafka-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Robin Yamaguchi <ro...@hasoffers.com>
Subject Controller to broker connection timing out through load balancer
Date Thu, 08 May 2014 21:19:32 GMT
Greetings,

I'm looking for some feedback with using advertised.host.name and
advertised.port on kafka 0.8.1.1 through a load balancer.  The brokers are
fronted with haproxy to support our cluster mirroring configuration.  The
setup has been working as expected, where producers, consumers, and broker
connections go through haproxy.  I am however sometimes getting errors when
attempting to create a new topic:

2014-05-08 19:00:49,757 - WARN
 [Controller-0-to-broker-0-send-thread:Logging$class@89] -
[Controller-0-to-broker-0-send-thread], Controller 0 fails to send a
request to broker id:0,host:localhost,port:13000
java.io.EOFException: Received -1 when reading from channel, socket has
likely been closed.
at kafka.utils.Utils$.read(Utils.scala:376)
at
kafka.network.BoundedByteBufferReceive.readFrom(BoundedByteBufferReceive.scala:54)
at kafka.network.Receive$class.readCompletely(Transmission.scala:56)
at
kafka.network.BoundedByteBufferReceive.readCompletely(BoundedByteBufferReceive.scala:29)
at kafka.network.BlockingChannel.receive(BlockingChannel.scala:100)
at
kafka.controller.RequestSendThread.doWork(ControllerChannelManager.scala:146)
at kafka.utils.ShutdownableThread.run(ShutdownableThread.scala:51)
2014-05-08 19:00:49,769 - ERROR
[Controller-0-to-broker-0-send-thread:Logging$class@103] -
[Controller-0-to-broker-0-send-thread], Controller 0 epoch 2 failed to send
UpdateMetadata request with correlation id 7 to broker
id:0,host:localhost,port:13000. Reconnecting to broker.
java.nio.channels.ClosedChannelException
at kafka.network.BlockingChannel.send(BlockingChannel.scala:89)
at
kafka.controller.RequestSendThread.liftedTree1$1(ControllerChannelManager.scala:132)
at
kafka.controller.RequestSendThread.doWork(ControllerChannelManager.scala:131)
at kafka.utils.ShutdownableThread.run(ShutdownableThread.scala:51)
2014-05-08 19:00:49,770 - INFO
 [Controller-0-to-broker-0-send-thread:Logging$class@68] -
[Controller-0-to-broker-0-send-thread], Controller 0 connected to
id:0,host:localhost,port:13000 for sending state change requests


When receiving this error, the new topic is registered in zookeeper, but
not written to disk by the broker.  The topic however will be written to
disk the next time the kafka broker is restarted.  I did not experience
this behavior in other clusters that are not fronted by a load balancer.  I
also do not get this error when kafka is initially started.

To help simplify troubleshooting, I setup a single host with kafka,
zookeeper, and haproxy running on it with these relevant configurations:

Kafka:
advertised.host.name = localhost
advertised.port = 13000

Zookeeper:
port = default

Haproxy:
listen kafka_13000 0.0.0.0:13000
mode tcp
option tcpka
timeout client 5m
timeout server 5m
timeout connect 5m
server h-kafka01-1b localhost:9092

Here are the network sockets Kafka creates on start-up:

[root@dp-robin01-dev.sea1.office.priv kafka]# lsof -i -P | grep -i kafka
java      25532     kafka   18u  IPv6 14717680      0t0  TCP *:44398
(LISTEN)
java      25532     kafka   23u  IPv6 14717684      0t0  TCP
localhost.localdomain:58093->localhost.localdomain:2181 (ESTABLISHED)
java      25532     kafka   38u  IPv6 14717692      0t0  TCP *:9092 (LISTEN)
java      25532     kafka   39u  IPv6 14717694      0t0  TCP
localhost.localdomain:45037->localhost.localdomain:13000 (ESTABLISHED)
java      25532     kafka   40u  IPv6 14717698      0t0  TCP
localhost.localdomain:9092->localhost.localdomain:46448 (ESTABLISHED)


After the 5m timeout configured in haproxy is surpassed, the connection
through port 13000 is closed (from kafka.log):

2014-05-08 19:05:40,904 - INFO  [kafka-processor-9092-0:Logging$class@68] -
Closing socket connection to /127.0.0.1.


Looking again at the network sockets, the controller to broker connection
is in a CLOSE_WAIT state:

[root@dp-robin01-dev.sea1.office.priv kafka]# lsof -i -P | grep -i kafka
java      25532     kafka   18u  IPv6 14717680      0t0  TCP *:44398
(LISTEN)
java      25532     kafka   23u  IPv6 14717684      0t0  TCP
localhost.localdomain:58093->localhost.localdomain:2181 (ESTABLISHED)
java      25532     kafka   38u  IPv6 14717692      0t0  TCP *:9092 (LISTEN)
java      25532     kafka   39u  IPv6 14717694      0t0  TCP
localhost.localdomain:45037->localhost.localdomain:13000 (CLOSE_WAIT)


This is when attemping to create a topic will error with:
java.io.EOFException: Received -1 when reading from channel, socket has
likely been closed.

The linux kernel will remove the socket in a CLOSE_WAIT state after the tcp
keepalive expires, which defaults to 2 hours:

[root@dp-robin01-dev.sea1.office.priv kafka]# ss -o | grep 13000
CLOSE-WAIT 1      0        ::ffff:127.0.0.1:45040
::ffff:127.0.0.1:13000   timer:(keepalive,46sec,0)


List of kafka sockets after the controller to broker connection has been
completely removed:

[root@dp-robin01-dev.sea1.office.priv kafka]# lsof -i -P | grep -i kafka
java      25532     kafka   18u  IPv6 14717680      0t0  TCP *:44398
(LISTEN)
java      25532     kafka   23u  IPv6 14717684      0t0  TCP
localhost.localdomain:58093->localhost.localdomain:2181 (ESTABLISHED)
java      25532     kafka   38u  IPv6 14717692      0t0  TCP *:9092 (LISTEN)


Now when attempting to create a new topic, Kafka detects that the
controller to broker connection is down, reconnects successfully, and is
able to write topic to disk:

2014-05-08 21:02:47,685 - INFO
 [ZkClient-EventThread-12-localhost:2181:Logging$class@68] - [Partition
state machine on Controller 0]: Invoking state change to OnlinePartition
for partitions
[Test2,1],[Test2,14],[Test2,3],[Test2,12],[Test2,0],[Test2,13],[Test2,4],[Test2,6],[Test2,9],[Test2,15],[Test2,2],[Test2,7],[Test2,11],[Test2,5],[Test2,8],[Test2,10]
2014-05-08 21:02:47,796 - ERROR
[Controller-0-to-broker-0-send-thread:Logging$class@103] -
[Controller-0-to-broker-0-send-thread], Controller 0 epoch 2 failed to send
LeaderAndIsr request with correlation id 11 to broker
id:0,host:localhost,port:13000. Reconnecting to broker.
java.io.IOException: Broken pipe
at sun.nio.ch.FileDispatcherImpl.writev0(Native Method)
at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:51)
at sun.nio.ch.IOUtil.write(IOUtil.java:148)
at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:524)
at java.nio.channels.SocketChannel.write(SocketChannel.java:493)
at
kafka.network.BoundedByteBufferSend.writeTo(BoundedByteBufferSend.scala:56)
at kafka.network.Send$class.writeCompletely(Transmission.scala:75)
at
kafka.network.BoundedByteBufferSend.writeCompletely(BoundedByteBufferSend.scala:26)
at kafka.network.BlockingChannel.send(BlockingChannel.scala:92)
at
kafka.controller.RequestSendThread.liftedTree1$1(ControllerChannelManager.scala:132)
at
kafka.controller.RequestSendThread.doWork(ControllerChannelManager.scala:131)
at kafka.utils.ShutdownableThread.run(ShutdownableThread.scala:51)
2014-05-08 21:02:47,802 - INFO
 [Controller-0-to-broker-0-send-thread:Logging$class@68] -
[Controller-0-to-broker-0-send-thread], Controller 0 connected to
id:0,host:localhost,port:13000 for sending state change requests


It seems that the controller isn't able to properly resolve a connection in
a CLOSE_WAIT state.  The exceptions thrown is different from when the
socket is in a CLOSE_WAIT vs not existing at all.

I can somewhat work around this issue by lowering the kernel tcp keepalive
settings and increasing my haproxy timeouts, but thats not very desirable
and wouldn't work 100% of the time.  I've looked through the broker
configuration documentation, and didn't get any meaningful results changing
controller.socket.timeout.ms.

Any feedback / suggestions would be greatly appreciated.

Thank you,
Robin

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message