Handle 0.9 broker's idle connection reaper

[ah-]

I'm running librdkafka built from the 0.9.0 branch with Kafka 0.9 on osx and every once in a while I see these messages popping up:

%3|1448840086.601|FAIL|rdkafka#producer-0| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1448840086.601|ERROR|rdkafka#producer-0| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1448840086.601|FAIL|rdkafka#producer-0| 127.0.0.1:9092/bootstrap: Connection closed
%3|1448840086.601|ERROR|rdkafka#producer-0| 127.0.0.1:9092/bootstrap: Connection closed
%3|1448840686.772|FAIL|rdkafka#producer-0| 192.168.0.3:9092/0: Receive failed: Disconnected
%3|1448840686.772|ERROR|rdkafka#producer-0| 192.168.0.3:9092/0: Receive failed: Disconnected
%3|1448840686.772|FAIL|rdkafka#producer-0| 192.168.0.3:9092/0: Connection closed
%3|1448840686.772|ERROR|rdkafka#producer-0| 192.168.0.3:9092/0: Connection closed

I think they coincide with this in the Kafka logs:

[2015-11-29 23:07:14,958] ERROR Processor got uncaught exception. (kafka.network.Processor)
java.lang.IllegalStateException: connectionId has unexpected format: fe80:0:0:0:0:0:0:1%1:9092-fe80:0:0:0:0:0:0:1%1:50070
        at kafka.network.Processor$$anonfun$run$13$$anonfun$7.apply(SocketServer.scala:447)
        at kafka.network.Processor$$anonfun$run$13$$anonfun$7.apply(SocketServer.scala:447)
        at scala.Option.getOrElse(Option.scala:121)
        at kafka.network.Processor$$anonfun$run$13.apply(SocketServer.scala:446)
        at kafka.network.Processor$$anonfun$run$13.apply(SocketServer.scala:445)
        at scala.collection.Iterator$class.foreach(Iterator.scala:742)
        at scala.collection.AbstractIterator.foreach(Iterator.scala:1194)
        at scala.collection.IterableLike$class.foreach(IterableLike.scala:72)
        at scala.collection.AbstractIterable.foreach(Iterable.scala:54)
        at kafka.network.Processor.run(SocketServer.scala:445)
        at java.lang.Thread.run(Thread.java:745)

Everything keeps working perfectly, but I suspect this is not supposed to happen. Any idea?

[edenhill]

Do you get these connects every 10 minutes?
The 0.9.0 broker added connections.max.idle.ms (with a default of 10 minutes) which is unfortunately the same interval librdkafka sends metadata requests (topic.metadata.refresh.interval.ms).
It is not sufficient to simply decrease the refresh interval since librdkafka only queries one of the brokers, so I'm working on a proper fix for these idle timeouts.
On the other hand there is really no impact, apart from the extra log messages, since it is only idle broker connections that are torn down.

[ah-]

Yes, it always happens only in 10 minute intervals, but not always every 10 minutes.

What's your intended fix? Send heartbeats every couple of minutes?

[edenhill]

This is a bit tricky since there is no side-effect free protocol request to use for heartbeats.

MetadataRequests to list all topics is a read-only operation, but on a cluster with many topics&partitions its processing time is non-negligible.
MetadataRequests to list only the topics we are interested in is slimmer but will create the topic(s) if topic auto-creation is enabled on the brokers. So this would be an undesired side-effect.

My longer term plan is to make sparse broker connections: only connect to the brokers we need to talk to, and only do so when we have something to say. In this case the idle disconnects are even desired.

[skandragon]

What problem was this idle timeout intended to solve?

[edenhill]

No idea, and SO_KEEPALIVE would've been the proper answer to whatever the initial problem was :)

[skandragon]

Probably. Can we just remove this misfeature? :)

[edenhill]

With a wider definition (kafka-dev@) of we, sure we can! :)

[skandragon]

I guess, if we have to deal with this, at the least not having an expected thing produce error messages is good. That's our current problem -- it's too noisy and looks like errors, and we will get support calls.

[edenhill]

This is the original issue:
https://issues.apache.org/jira/browse/KAFKA-1282

Seems to be mostly an issue on broker fd resources.

You can control the idle timeout on the broker through: connections.max.idle.ms

[skandragon]

IMHO, if the broker is running out of fd resources, idle timeout is just going to make it harder to diagnose as it moves new-things-connecting-fail to old-things-connecting-fail-seemingly-at-random but as you said, it's in the broker. Regardless, we should not error on a closed connection for a producer in librdkafka.

[edenhill]

Regardless, we should not error on a closed connection for a producer in librdkafka.

What's the definition of "we" here? Should I be doing something?

[skandragon]

I think rdkafka should not print out errors on closed connections, but it should print out errors when it cannot connect. This way, the idle timeout thing does not cause the appearance of a fault, and we (at least) will be happy. :)