Fixing out-kafka plugin hung issue

[serkantkaraca]

rd-kafka plugin cannot recover RD_KAFKA_RESP_ERR__QUEUE_FULL error due to a bug at the retry logic.

Addressing the issues reported at
#2161
#2244

With current implementation, once the queue-full retry is exhausted, there is no task left checking underlying librdkafka buffer to unblock upstream calls. In other words, once limit of 10 retries filled up, rdkafka plugin becomes blocked indefinitely and then the only way to recover is to kill that pod.

Testing

• [ X] Example configuration file for the change

[SERVICE]
Flush 1
Daemon off
Log_Level info

[INPUT]
Name cpu
Tag cpu
Interval_Sec 0
Interval_NSec 10000000

[OUTPUT]
Name kafka
Match *
Brokers 10.91.40.55:9092
Topics testtopic
Timestamp_Key @timestamp
#Retry_Limit 5
rdkafka.log.connection.close false
rdkafka.queue.buffering.max.kbytes 100
#rdkafka.queue.buffering.max.messages 100000
#rdkafka.request.required.acks 1
#rdkafka.message.max.bytes 1000000
#rdkafka.linger.ms 1000
#rdkafka.socket.timeout.ms 30000
#rdkafka.batch.num.messages 10000
#rdkafka.message.timeout.ms 120000
rdkafka.retries 100000
rdkafka.retry.backoff.ms 3000
#rdkafka.request.timeout.ms 60000
#rdkafka.metadata.max.age.ms 180000
rdkafka.max.in.flight.requests.per.connection 1
rdkafka.debug broker,topic,msg,queue

Fluent Bit is licensed under Apache 2.0, by submitting this pull request I understand that this code will be released under the terms of that license.

[edsiper]

thanks for your contribution.

I have not tested the logic proposed, but what I see is that there is a chance that the flush() callback never returns if librdkafka keeps in a loop indefinitely retrying, shoulnd't we have a limit ?

[serkantkaraca]

thanks for your contribution.

I have not tested the logic proposed, but what I see is that there is a chance that the flush() callback never returns if librdkafka keeps in a loop indefinitely retrying, shoulnd't we have a limit ?

Why do you need flush to return if the sink is not ready to handle next flush?

[edsiper]

Flushes are not sequential, they are concurrent. It's better if we (Fluent Bit core) can handle the retry logic than the underlying external library... I think offering a config property for that would be ideal, users who don't want it might disable it easily, what do you think ?

[serkantkaraca]

You mean a rdkafka pluging config like 'DontRetryOnQueuFull'? Even for that case, we should make sure plugin is not hung when retry is opted in. Please feel free to update this one or send a new PR. I know what the issue is however I am not a Fluent-Bit expert, so my contributions may be limited. On the other hand, I can surely help testing the fix.

[isaidashev]

How are you doing with the problem? I can help with the test.

[serkantkaraca]

Any updates from review board?

[ghost]

Any update on this?

This issue causes actual message loss per the fb log, plus sigfaults where fb eventually crashes:

1. Connections to the kafka broker time out and disconnect, so FB librdkafka fills its buffer and often crashes:

[error] [output:kafka:kafka.3] fluent-bit#producer-2: [thrd:sasl_ssl://mykafkaeventhub]: sasl_ssl://mykafkaeventhub:9093/0: 1 request(s) timed out: disconnect

[ warn] [output:kafka:kafka.3] message delivery failed: Local: Message timed out

2.   Or, FB claims the broker disconnected whilst FB librdkafka fills its buffer (and doesn’t get an ACK but message may have been delivered?):
   

   [ warn] [input] tail.0 paused (mem buf overlimit)

   [ info] [input] tail.0 resume (mem buf overlimit)

   [ warn] [output:kafka:kafka.3] message delivery failed: Broker: Broker disconnected before response received

[serkantkaraca]

We have an important Azure customer blocked on this issue. Can we please get some attention on both the issue and the PR?

[edsiper]

@serkantkaraca

thanks for the update.

I think the PR do not solve the root cause of the problem but provides a workaround for your use case. I would like to suggest a mid-point workaround that don't affect other users, because the current logic "blocks" Fluent Bit until the data can be enqueued.

I think the mid-point is to make the "retries" inside the kafka plugin configurable instead of being infinite. If you agree with that I can make the requirement adjustments.

all, please provide feedback today since the release is tomorrow.

[serkantkaraca]

@edsiper that will also do. Can you make sure that we are allowing retry-indefinitely option maybe by setting MaxRetryCount to "zero" or some literal?

[edsiper]

sure.

I will push the commit shortly.

[edsiper]

@serkantkaraca I've pushed fix b8053b7 for this enhancement.

Please test it and send me some feedback

[serkantkaraca]

Thanks @edsiper for quick turnaround!

[tarun-wadhwa-mmt]

Was testing with fluentbit 1.6.0 and experiencing the same issue. The output to kafka just stops. CPU suddenly shoots 100% and there is no error in debug logs as well..

How can i extract relevant information to debug this?

[serkantkaraca]

Testing on 1.6.0 and so far so good. I haven't seen any issue so far with queue_full_retries=10000.

[ghost]

Ditto, I've been testing it at a low scale but will start scale tests next week to several million events per second in conjunction with a new symmetric aes encryption C filter I've been writing to secure kubernetes logs end to end stored in the cloud. Thanks!

…

On Mon, 12 Oct 2020, 21:50 Serkant Karaca, ***@***.***> wrote: Testing on 1.6.0 and so far so good. I haven't seen any issue so far with queue_full_retries=10000. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#2553 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/APCC4KRQWT4R737LBTJRQNDSKNTY5ANCNFSM4RN4MRFQ> .

[GiedriusS]

This still doesn't seem like a very good solution.

In other words, once limit of 10 retries filled up, rdkafka plugin becomes blocked indefinitely and then the only way to recover is to kill that pod.

This is pretty cool but IMO we should retry sending data that we have regardless of this option. It is a pretty dire situation that FLB can get stuck. I really, really, really don't want to wake up in the middle of the night to restart some pods in k8s just because queue_full_retries has been reached (whatever number that is). I think we should permit the engine to try one more time to send some data again if the queues get blocked. I have outlined all of the details here: #2894. PTAL if it makes sense 🤗