Librdkafka: Handle 0.9 broker's idle connection reaper

Created on 30 Nov 2015 · 34Comments · Source: edenhill/librdkafka

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?

enhancement

Source

ah-

👍4

Most helpful comment

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.

edenhill on 11 Jan 2016

👍6

All 34 comments

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.

edenhill on 30 Nov 2015

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?

ah- on 11 Jan 2016

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

edenhill on 11 Jan 2016

👍6

What problem was this idle timeout intended to solve?

skandragon on 14 Jan 2016

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

edenhill on 14 Jan 2016

Probably. Can we just remove this misfeature? :)

skandragon on 14 Jan 2016

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

edenhill on 14 Jan 2016

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.

skandragon on 14 Jan 2016

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

edenhill on 14 Jan 2016

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.

skandragon on 14 Jan 2016

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?

edenhill on 14 Jan 2016

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. :)

skandragon on 14 Jan 2016

Not logging in this scenario makes sense, but in other scenarios it might be useful for troubleshooting.
So I'd like to keep the default but maybe make it configurable. There are two options:

log.connection.close=true|false
dont log connection close if connection has been idle for more than connection.idle.max.ms.something.log.maybe=<same value as broker>

The latter is more useful in my opinion but requires (well, not really) this config value to be in sync with the broker. We could use a reasonable default for it, e.g. the broker default (!)

edenhill on 14 Jan 2016

👍1

It's something of a shame we can't query the broker for config information, or topics for topic config that is defaulted via broker config. But I digress.

I'm fine with the latter, but the former is better I think. This closed connection is not a fatal error, but failure to connect is a failure. I guess it comes down to WHY log in the case where a connection is dropped, but then can be re-established.

BTW, does librdkafka just immediately reconnect, or does it wait until it has something to send? If the former, then I really don't understand this new broker option, since I bet everyone will just do the same thing -- we want to be in contact so we can send messages immediately.

skandragon on 14 Jan 2016

Re behaviour: librdkafka keeps connected to all brokers it knows about (which is all brokers in the cluster) and reconnects "immediately" (see reconnect.backoff.jitter.ms).

But sure, log.connection.close is a quick fix, we can add the heuristic one later.

edenhill on 14 Jan 2016

Sounds good!

skandragon on 14 Jan 2016

Give it a try.

edenhill on 15 Jan 2016

👍4

Seeing the exact same behavior but every 300 seconds but the connections.max.idle.ms is set to default 10 mins. Could it be the same thing?

%3|1458444064.863|FAIL|rdkafka#producer-80| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444064.937|FAIL|rdkafka#producer-91| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444064.966|FAIL|rdkafka#producer-81| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444065.046|FAIL|rdkafka#producer-105| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444065.092|FAIL|rdkafka#producer-57| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444065.103|FAIL|rdkafka#producer-82| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444065.168|FAIL|rdkafka#producer-112| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444065.218|FAIL|rdkafka#producer-107| localhost:9092/0: Receive failed: Disconnected
%3|1458444065.219|FAIL|rdkafka#producer-94| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444065.307|FAIL|rdkafka#producer-111| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444065.424|FAIL|rdkafka#producer-72| localhost:9092/0: Receive failed: Disconnected
%3|1458444364.214|FAIL|rdkafka#producer-6| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444364.287|FAIL|rdkafka#producer-1| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444364.329|FAIL|rdkafka#producer-11| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444364.387|FAIL|rdkafka#producer-9| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444364.424|FAIL|rdkafka#producer-29| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444364.425|FAIL|rdkafka#producer-19| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444364.457|FAIL|rdkafka#producer-22| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444364.541|FAIL|rdkafka#producer-40| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444364.575|FAIL|rdkafka#producer-45| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444364.618|FAIL|rdkafka#producer-48| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444364.661|FAIL|rdkafka#producer-58| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected
%3|1458444364.662|FAIL|rdkafka#producer-16| 127.0.0.1:9092/bootstrap: Receive failed: Disconnected

rahar on 20 Mar 2016

@rahar Could it be TCP keepalives? (needs to be explicitly enabled)
What are the broker logs saying?

edenhill on 28 Mar 2016

@edenhill i got same error for ERROR Processor got uncaught exception.

put log.connection.close=true|false to where? server.properties?

nathan-zhu on 31 Mar 2016

@nathan-zhu That's a librdkafka config property. Can you show the entire stacktrace from the broker's "Process got uncaught exception"?

edenhill on 31 Mar 2016

The solution is the following. Set kafka to listen on one network interface
only.

rahar on 31 Mar 2016

@edenhill could you share more about how to use this config property: log.connection.close?

didowill on 28 Jun 2016

@didowill log.connection.close=true simply disables the logging of broker socket disconnects. It is used to silence disconnects (probably) caused by the Kafka broker's idle connection reaper.

edenhill on 30 Jun 2016

I think this works well enough.

edenhill on 29 Aug 2016

I still receive a ton of these messages whether I use ["log.connection.close"] = "true", or ["log.connection.close"] = "false", to the point where it can cause the disk to fill up (we log stdout/stderr).

Was there any further resolution on this? I would think anything that says FAIL or ERROR and then "No error" is a bug.

llinsky on 29 Jun 2017

SSL disconnects printed "No error", which was a bug, but is fixed on master and 0.11.0-RC2.
The final release is imminent.

edenhill on 29 Jun 2017

Ah, that makes sense. Thanks.

llinsky on 29 Jun 2017

Is there any intent to change librdkafka's handling of disconnections? Doesn't the current behavior defeat the purpose of the idle disconnect feature and arguably make it worse?

trapexit on 31 Aug 2017

@trapexit Yes, we'll implement sparse(r) broker connections eventually, it is on the backlog and tracked in issue https://github.com/edenhill/librdkafka/issues/825

I don't have a timeframe yet.

edenhill on 31 Aug 2017

Guys, can someone tell me where to put log.connection.close=true|false to where? server.properties? It maybe a strange question, but i really do not understand where those props should be set...

alexiicon on 9 Oct 2018

@alexiicon It is a client configuration property.
If you are using the C API simply do rd_kafka_conf_set(conf, "log.connection.close", "false", NULL, 0); on the config object you later pass to rd_kafka_new().

edenhill on 9 Oct 2018

Does this issue solve after sparse connection support?