fluent / fluent/fluent-bit

Backoff timer is not applied to chunks globally

Open
#5,613 14 comments 1 reaction 0 assignees View on GitHub
exempt-stale status: waiting-for-triage
Dominant language
C
Stars
8.1k
Forks
2k
Avg merge
4d 16h
Merged PRs (30d)
58

Description

## Bug Report

**Describe the bug**

Fluent Bit appears to be applying the retry delay for each individual chunk but it keeps trying to send new chunks from the logs it is tailing without any delay. The `Retry_Limit` and `scheduler` settings appear to have no effect on this behavior, because technically these are not retries, but rather continued attempts to send new chunks even when the destination has been consistently unavailable for previous chunks.

In our case, this caused a DoS on our CoreDNS server. We have Fluent Bit set up as log tailer on our k8s nodes, sending to [Vector](https://vector.dev/)'s Fluent source. If Fluent Bit is deployed before Vector, the vector hostname will not exist in DNS yet, and Fluent Bit will just keep spamming DNS requests for each new chunk. This caused a total of 1.2M DNS requests in less than 15 minutes and caused our CoreDNS pods to OOM. DNS for the entire cluster was unavailable and resulted in downtime for other customer-facing applications.

This is aggregated across all 189 fluent pods in our k8s cluster:

```
$ grep "Timeout while contacting DNS servers" fluent-bit-567850229182.log | wc -l
1275364
```

```
$ grep "Timeout while contacting DNS servers" fluent-bit-567850229182.log | awk '{print $2}' | cut -d: -f1,2 | sort | uniq -c
1 19:47
41112 19:48
78822 19:49
88603 19:50
101609 19:51
104123 19:52
113327 19:53
95675 19:54
52299 19:55
125746 19:56
126956 19:57
128904 19:58
131091 19:59
87096 20:00
```

Logs start out looking like this:

```
[2022/06/21 19:47:33] [ warn] [net] getaddrinfo(host='vector.platform-observability', err=4): Domain name not found
[2022/06/21 19:47:33] [error] [output:forward:forward.0] no upstream connections available
[2022/06/21 19:47:33] [ warn] [engine] failed to flush chunk '1-1655840852.784688832.flb', retry in 8 seconds: task_id=0, input=tail.1 > output=forward.0 (out_id=0)
[2022/06/21 19:47:34] [ warn] [net] getaddrinfo(host='vector.platform-observability', err=4): Domain name not found
[2022/06/21 19:47:34] [error] [output:forward:forward.0] no upstream connections available
[2022/06/21 19:47:34] [ warn] [engine] failed to flush chunk '1-1655840853.538056562.flb', retry in 10 seconds: task_id=2, input=systemd.2 > output=forward.0 (out_id=0)
[2022/06/21 19:47:34] [ warn] [net] getaddrinfo(host='vector.platform-observability', err=4): Domain name not found
[2022/06/21 19:47:34] [error] [output:forward:forward.0] no upstream connections available
```

Then after a few seconds we start getting timeouts as the DNS server gets overloaded:

```
[2022/06/21 19:47:59] [ warn] [engine] failed to flush chunk '1-1655840868.200737091.flb', retry in 19 seconds: task_id=25, input=tail.1 > output=forward.0 (out_id=0)
[2022/06/21 19:48:08] [ warn] [net] getaddrinfo(host='vector.platform-observability', err=12): Timeout while contacting DNS servers
[2022/06/21 19:48:08] [error] [output:forward:forward.0] no upstream connections available
[2022/06/21 19:48:08] [ warn] [net] getaddrinfo(host='vector.platform-observability', err=12): Timeout while contacting DNS servers
[2022/06/21 19:48:08] [error] [output:forward:forward.0] no upstream connections available
[2022/06/21 19:48:08] [ warn] [engine] failed to flush chunk '1-1655840871.198934080.flb', retry in 7 seconds: task_id=28, input=tail.0 > output=forward.0 (out_id=0)
[2022/06/21 19:48:08] [ warn] [engine] failed to flush chunk '1-1655840872.200573639.flb', retry in 15 seconds: task_id=32, input=tail.1 > output=forward.0 (out_id=0)
[2022/06/21 19:48:08] [ warn] [net] getaddrinfo(host='vector.platform-observability', err=12): Timeout while contacting DNS servers
[2022/06/21 19:48:08] [error] [output:forward:forward.0] no upstream connections available
[2022/06/21 19:48:08] [ warn] [engine] failed to flush chunk '1-1655840878.200794762.flb', retry in 6 seconds: task_id=40, input=tail.1 > output=forward.0 (out_id=0)
[2022/06/21 19:48:08] [ warn] [net] getaddrinfo(host='vector.platform-observability', err=11): Could not contact DNS servers
[2022/06/21 19:48:08] [error] [output:forward:forward.0] no upstream connections available
```

Finally after Vector is deployed and CoreDNS is restarted, chunks start to succeed:

```
[2022/06/21 20:00:49] [ info] [engine] flush chunk '1-1655841607.404448798.flb' succeeded at retry 3: task_id=1147, input=tail.0 > output=forward.0 (out_id=0)
[2022/06/21 20:00:49] [ info] [engine] flush chunk '1-1655841632.662283630.flb' succeeded at retry 2: task_id=1190, input=systemd.2 > output=forward.0 (out_id=0)
[2022/06/21 20:00:49] [ info] [engine] flush chunk '1-1655840896.109007641.flb' succeeded at retry 7: task_id=61, input=tail.1 > output=forward.0 (out_id=0)
[2022/06/21 20:00:49] [ info] [engine] flush chunk '1-1655840866.200703985.flb' succeeded at retry 7: task_id=22, input=tail.1 > output=forward.0 (out_id=0)
```

**To Reproduce**
- Example log message if applicable: See above.
- Steps to reproduce the problem: See above.

**Expected behavior**

Fluent bit should a retry delay to all DNS requests globally, not just on a per-chunk basis.

**Your Environment**

* Version used: 1.9.5
* Configuration:

```
[OUTPUT]
Name forward
Match *
# update these to point to your vector instance
Host {{ .Values.vector.host }}
Port {{ .Values.vector.port }}
Retry_Limit 3
```

* Environment name and version (e.g. Kubernetes? What version?): Kubernetes 1.18.20-eks
* Filters and plugins: No plugins. Filters: modify, grep, kuberentes

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.