Timeouts after upgrading to 1.8.5 #4042

rmarchei · 2021-09-02T07:47:21Z

Bug Report

After upgrading to 1.8.5 fluentbit time outs while connecting to fluentd:

Sep 02 00:27:20 admin01 fluent-bit[121051]: [2021/09/02 00:27:20] [error] [upstream] connection #-1 to fluentd.service.consul:24224 timed out after 10 seconds
Sep 02 00:27:56 admin01 fluent-bit[121051]: [2021/09/02 00:27:56] [error] [upstream] connection #-1 to fluentd.service.consul:24224 timed out after 10 seconds

Output is configured as:

[OUTPUT]
    Name                 forward
    Match                fluentd.*
    Host                 fluentd.service.consul
    Port                 24224
    Require_ack_response True

fluentd.service.consul can be resolved without issues and it's even in /etc/hosts

Same behavior with 1.8.6. Downgrading to 1.8.4 solves the issue

Everything is running on Ubuntu 20.04.3.
Fluentbit version: td-agent-bit 1.8.5
Fluentd version: td-agent 4.2.0-1

Full log from last fluentbit restart:

Sep 02 00:27:05 admin01 systemd[1]: Started Fluent Bit.
Sep 02 00:27:05 admin01 fluent-bit[121051]: Fluent Bit v1.8.6
Sep 02 00:27:05 admin01 fluent-bit[121051]: * Copyright (C) 2019-2021 The Fluent Bit Authors
Sep 02 00:27:05 admin01 fluent-bit[121051]: * Copyright (C) 2015-2018 Treasure Data
Sep 02 00:27:05 admin01 fluent-bit[121051]: * Fluent Bit is a CNCF sub-project under the umbrella of Fluentd
Sep 02 00:27:05 admin01 fluent-bit[121051]: * https://fluentbit.io
Sep 02 00:27:05 admin01 fluent-bit[121051]: [2021/09/02 00:27:05] [ info] [engine] started (pid=121051)
Sep 02 00:27:05 admin01 fluent-bit[121051]: [2021/09/02 00:27:05] [ info] [storage] version=1.1.1, initializing...
Sep 02 00:27:05 admin01 fluent-bit[121051]: [2021/09/02 00:27:05] [ info] [storage] root path '/var/lib/fluentbit/storage'
Sep 02 00:27:05 admin01 fluent-bit[121051]: [2021/09/02 00:27:05] [ info] [storage] normal synchronization mode, checksum disabled, max_chunks_up=128
Sep 02 00:27:05 admin01 fluent-bit[121051]: [2021/09/02 00:27:05] [ info] [storage] backlog input plugin: storage_backlog.1
Sep 02 00:27:05 admin01 fluent-bit[121051]: [2021/09/02 00:27:05] [ info] [cmetrics] version=0.2.1
Sep 02 00:27:05 admin01 fluent-bit[121051]: [2021/09/02 00:27:05] [ info] [input:storage_backlog:storage_backlog.1] queue memory limit: 4.8M
Sep 02 00:27:05 admin01 fluent-bit[121051]: [2021/09/02 00:27:05] [ info] [sp] stream processor started
Sep 02 00:27:05 admin01 fluent-bit[121051]: [2021/09/02 00:27:05] [ info] [input:tail:tail.user_action] inotify_fs_add(): inode=774739 watch_fd=1 name=/var/log/app/mylog.log
Sep 02 00:27:20 admin01 fluent-bit[121051]: [2021/09/02 00:27:20] [error] [upstream] connection #-1 to fluentd.service.consul:24224 timed out after 10 seconds
Sep 02 00:27:56 admin01 fluent-bit[121051]: [2021/09/02 00:27:56] [error] [upstream] connection #-1 to fluentd.service.consul:24224 timed out after 10 seconds

The text was updated successfully, but these errors were encountered:

capricornusx · 2021-09-07T08:55:08Z

Same case (connect to elasticsearch)

Ubuntu 20.04.3 LTS
Fluent Bit 1.8.6
Elasticsearch 7.14.0

Downgrading to 1.8.4 solves the issue

Sep 07 08:46:49 monitoring td-agent-bit[1550873]: * Fluent Bit is a CNCF sub-project under the umbrella of Fluentd
Sep 07 08:46:49 monitoring td-agent-bit[1550873]: * https://fluentbit.io
Sep 07 08:46:49 monitoring td-agent-bit[1550873]: [2021/09/07 08:46:49] [ info] [engine] started (pid=1550873)
Sep 07 08:46:49 monitoring td-agent-bit[1550873]: [2021/09/07 08:46:49] [ info] [storage] version=1.1.1, initializing...
Sep 07 08:46:49 monitoring td-agent-bit[1550873]: [2021/09/07 08:46:49] [ info] [storage] root path '/storage'
Sep 07 08:46:49 monitoring td-agent-bit[1550873]: [2021/09/07 08:46:49] [ info] [storage] normal synchronization mode, checksum enabled, max_chunks_up=128
Sep 07 08:46:49 monitoring td-agent-bit[1550873]: [2021/09/07 08:46:49] [ info] [storage] backlog input plugin: storage_backlog.1
Sep 07 08:46:49 monitoring td-agent-bit[1550873]: [2021/09/07 08:46:49] [ info] [cmetrics] version=0.2.1
Sep 07 08:46:49 monitoring td-agent-bit[1550873]: [2021/09/07 08:46:49] [ info] [input:forward:main_input] listening on 0.0.0.0:24224
Sep 07 08:46:49 monitoring td-agent-bit[1550873]: [2021/09/07 08:46:49] [ info] [input:storage_backlog:storage_backlog.1] queue memory limit: 244.1M
Sep 07 08:46:49 monitoring td-agent-bit[1550873]: [2021/09/07 08:46:49] [ info] [http_server] listen iface=0.0.0.0 tcp_port=2021
Sep 07 08:46:49 monitoring td-agent-bit[1550873]: [2021/09/07 08:46:49] [ info] [sp] stream processor started
Sep 07 08:47:18 monitoring td-agent-bit[1550873]: [2021/09/07 08:47:18] [error] [upstream] connection #-1 to localhost:9200 timed out after 10 seconds
Sep 07 08:47:18 monitoring td-agent-bit[1550873]: [2021/09/07 08:47:18] [error] [upstream] connection #-1 to localhost:9200 timed out after 10 seconds
Sep 07 08:47:18 monitoring td-agent-bit[1550873]: [2021/09/07 08:47:18] [error] [upstream] connection #-1 to localhost:9200 timed out after 10 seconds
Sep 07 08:47:18 monitoring td-agent-bit[1550873]: [2021/09/07 08:47:18] [error] [upstream] connection #-1 to localhost:9200 timed out after 10 seconds
Sep 07 08:47:39 monitoring td-agent-bit[1550873]: [2021/09/07 08:47:39] [error] [upstream] connection #-1 to localhost:9200 timed out after 10 seconds
...

leonardo-albertovich · 2021-09-14T15:30:00Z

Hello folks, I'm working on this issue and I have a few questions for some of you which would probably make it easier to figure out if there is something that needs to be fixed and what if that's the case.

Are the timeouts sporadic or constant?
Do the timeouts show as soon as you start fluent-bit?
If they do not show as soon as you start fluent-bit, does fluent-bit ever go back to working fine once they start appearing or does it get stuck failing on every single attempt until you restart it?
Would you be able to provide your configuration files? (With any sensitive information redacted of course)
Can you easily reproduce the problem?

I noticed that @rmarchei mentioned DNS resolution but I didn't see any DNS related errors in there, a DNS error should cause fluent-bit to print something like this :

[ warn] [net] getaddrinfo(host='xxxxxxxxxxxxx.xxx', err=12): Timeout while contacting DNS servers

Thanks for reporting the issue, any further assistance in reproduction and troubleshooting would be greatly appreciated.

rmarchei · 2021-09-16T08:30:49Z

I think this issue has been fixed in #4050

rmarchei · 2021-09-20T19:35:53Z

actually it seems to be still broken in 1.8.7

* Are the timeouts sporadic or constant?

Constant:

Sep 20 12:26:10 front02 fluent-bit[1237001]: [2021/09/20 12:26:10] [error] [upstream] connection #-1 to fluentd.service.consul:24224 timed out after 10 seconds
Sep 20 12:26:14 front02 fluent-bit[1237001]: [2021/09/20 12:26:14] [error] [upstream] connection #-1 to fluentd.service.consul:24224 timed out after 10 seconds
Sep 20 12:26:19 front02 fluent-bit[1237001]: [2021/09/20 12:26:19] [error] [upstream] connection #-1 to fluentd.service.consul:24224 timed out after 10 seconds
Sep 20 12:26:25 front02 fluent-bit[1237001]: [2021/09/20 12:26:25] [error] [upstream] connection #-1 to fluentd.service.consul:24224 timed out after 10 seconds
Sep 20 12:26:29 front02 fluent-bit[1237001]: [2021/09/20 12:26:29] [error] [upstream] connection #-1 to fluentd.service.consul:24224 timed out after 10 seconds
Sep 20 12:26:34 front02 fluent-bit[1237001]: [2021/09/20 12:26:34] [error] [upstream] connection #-1 to fluentd.service.consul:24224 timed out after 10 seconds

* Do the timeouts show as soon as you start fluent-bit?

yes. To be precise, they appear as soon as parsed logs have new entries

* Would you be able to provide your configuration files? (With any sensitive information redacted of course)

Here you have the conf:

[SERVICE]
    flush                     5
    daemon                    off
    log_level                 info
    storage.path              /var/lib/fluentbit/storage
    storage.sync              normal
    storage.checksum          off
    storage.backlog.mem_limit 5M

    Parsers_File parsers.conf
    Plugins_File plugins.conf

    HTTP_Server  Off
    HTTP_Listen  127.0.0.1
    HTTP_Port    2020
[INPUT]
    Name             tail
    Alias            tail.user_action
    Tag              fluentd.rdb.archive.user_action
    Key              context
    Rotate_Wait      10
    Path             /var/log/test/fluentd/user_action.log
    Refresh_Interval 10
    Multiline        Off
    Parser           json
    DB               /var/lib/fluentbit/user_action.db
    DB.Sync          Extra
[FILTER]
    Name             record_modifier
    Match            fluentd.rdb.archive.user_action
    Whitelist_key    context
[FILTER]
    Name             nest
    Match            fluentd.rdb.archive.user_action
    Operation        lift
    Nested_under     context
[OUTPUT]
    Name                 forward
    Match                fluentd.*
    Host                 fluentd.service.consul
    Port                 24224
    Require_ack_response True
    Retry_Limit          False

* Can you easily reproduce the problem?

yes, I just have to install a version >1.8.4, restart fluentbit and the issue appears

leonardo-albertovich · 2021-09-21T15:03:42Z

Could you please message me in the fluent slack server to talk a little bit more about this?

rmarchei · 2021-09-21T15:18:20Z

Could you please message me in the fluent slack server to talk a little bit more about this?

sure, no problem. Which username (or channel) should I message?

leonardo-albertovich · 2021-09-21T15:28:07Z

Leonardo Almiñana

leonardo-albertovich · 2021-09-21T17:13:58Z

After carefully verifying the issue we (@rmarchei and I) found that when a hostname used as endpoint by an output plugin is present in the /etc/hosts file the DNS client changes the socket type and protocol returned from TCP to UDP which in the end is what caused the connection timeouts for him.

We are still investigating this issue to find the root cause. In the meantime, any users affected by this issue can comment or remove the /etc/hosts entry for the hostname in order to overcome it.

rolandjitsu · 2021-10-25T04:00:50Z

I'm seeing this in > v1.8.3 too with the forward output and even after #4122 was released in v1.8.8.

leonardo-albertovich · 2021-10-25T12:00:35Z

@rolandjitsu :

According to the source code v1.8.3 shouldn't be impacted by this particular issue as it was related to a change in how query sockets are created which was changed in v1.8.5 so I'd encourage you to submit a new issue with the appropriate information.

Regards.

rolandjitsu · 2021-10-26T10:22:28Z

@rolandjitsu :

According to the source code v1.8.3 shouldn't be impacted by this particular issue as it was related to a change in how query sockets are created which was changed in v1.8.5 so I'd encourage you to submit a new issue with the appropriate information.

Regards.

Ok. Thanks. One interesting behaviour I noticed is that if the network conn timeout is too low (e.g 5s), then the DNS issue ends up in no logs being sent. But if I set it to something like 30s, even if the DNS issue is reported, logs are still going through.

rmarchei mentioned this issue Sep 3, 2021

DNS resolution timeout/failure in >= 1.8.5 #4050

Closed

leonardo-albertovich mentioned this issue Sep 24, 2021

network: fixed a local resolution corner case #4122

Merged

leonardo-albertovich linked a pull request Sep 24, 2021 that will close this issue

network: fixed a local resolution corner case #4122

Merged

edsiper closed this as completed in #4122 Sep 25, 2021

paynejacob mentioned this issue Oct 6, 2021

[2.5] Update fluentbit to the latest version rancher/rancher#35058

Closed

PettitWesley mentioned this issue Oct 6, 2021

Datadog output failing to flush chunks #4157

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Timeouts after upgrading to 1.8.5 #4042

Timeouts after upgrading to 1.8.5 #4042

rmarchei commented Sep 2, 2021 •

edited

Loading

capricornusx commented Sep 7, 2021 •

edited

Loading

leonardo-albertovich commented Sep 14, 2021

rmarchei commented Sep 16, 2021

rmarchei commented Sep 20, 2021 •

edited

Loading

leonardo-albertovich commented Sep 21, 2021

rmarchei commented Sep 21, 2021

leonardo-albertovich commented Sep 21, 2021

leonardo-albertovich commented Sep 21, 2021

rolandjitsu commented Oct 25, 2021 •

edited

Loading

leonardo-albertovich commented Oct 25, 2021

rolandjitsu commented Oct 26, 2021

Timeouts after upgrading to 1.8.5 #4042

Timeouts after upgrading to 1.8.5 #4042

Comments

rmarchei commented Sep 2, 2021 • edited Loading

Bug Report

capricornusx commented Sep 7, 2021 • edited Loading

Same case (connect to elasticsearch)

leonardo-albertovich commented Sep 14, 2021

rmarchei commented Sep 16, 2021

rmarchei commented Sep 20, 2021 • edited Loading

leonardo-albertovich commented Sep 21, 2021

rmarchei commented Sep 21, 2021

leonardo-albertovich commented Sep 21, 2021

leonardo-albertovich commented Sep 21, 2021

rolandjitsu commented Oct 25, 2021 • edited Loading

leonardo-albertovich commented Oct 25, 2021

rolandjitsu commented Oct 26, 2021

rmarchei commented Sep 2, 2021 •

edited

Loading

capricornusx commented Sep 7, 2021 •

edited

Loading

rmarchei commented Sep 20, 2021 •

edited

Loading

rolandjitsu commented Oct 25, 2021 •

edited

Loading