aws-for-fluent-bit: Fluent-bit sidecar is killed because of networking error

I would like to ask you if there is any way to set up net.keepalive false via awsfirelens code automatically (without needing to manage the entire config by ourselves)

@angulito Its simple; the net.keepalive option is just like any other option

For example, your logConfiguration could be:

			 "logConfiguration": {
				 "logDriver":"awsfirelens",
				 "options": {
					"Name": "datadog",
					"apiKey": "<key>",
					"provider": "ecs",
					"dd_service": "my-app-service",
					"TLS": "On",
					"dd_source": "my-app",
                                        "net.keepalive": "false"
				}
			}

@florent-tails We also released aws-for-fluent-bit 2.7.0 (which includes fluent-bit 1.5.6) yesterday. If you want to play with it and report us back that would be great.

Hey @PettitWesley and @truthbk, I finally was able to reproduce the issue using valgrind. Here you have the fluent-bit logs fluent-bit-restart-logs.txt

Hope it helps. Let me know if I can help with anything else!

fluent/fluent-bit 1.5.6 has been released with some more fixes: https://fluentbit.io/announcements/v1.5.6/

We have been a bit busy lately… an AWS for Fluent Bit release should come sometime next week.

We don’t have a solution yet, but the suggestion in the PR is to try turning off keepalive to prevent the bad code path from being executed:

[OUTPUT]
    name            something
    match            *
    net.keepalive false

The behavior of different servers/endpoints must somehow influence this… we have 2 reports for datadog users; I don’t have any reports from users of AWS destinations.

We are also struggling to reproduce on Datadog’s end, still to no avail.

We have tried to simulate connetion failures and were able to force TCP resets by peer:

flb_io_tls.c:356 NET - Connection was reset by peer

But these were not following by segmentation faults or inapprioriate ioctl calls (though these may just be a red herring, these are not uncommon on TTY operations but should not crash the process).

It seems to me like this might be triggered not just by networking events/failures, but possibly also a race condition, in which case increasing the log rate to repro might help. If we do this, we must take into account the side-effects of valgrind (as amazing a tool as it is): because valgrind is essentially a VM that recompiles the source binary, and has an overhead that slow down runtime execution, it often makes it harder to trigger race conditions. So we might have to keep that in mind. It may be easier to enable core dumps if we can’t get good results with valgrind.

I think it’s safe to assume we’re all trying to reproduce on aws-for-fluent-bit: v2.6.1 (thus fluent-bit v1.5.2).

Also, I have come across this very similar case with the elasticsearch fluent bit plugin https://github.com/fluent/fluent-bit/issues/2416, so perhaps the issue is on the fluent bit core and not the plugins themselves.

@PettitWesley I am getting a lot of these error messages with v1.5.5:

[2020/09/08 22:46:59] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:46:59] [error] [src/flb_upstream.c:356 errno=25] Inappropriate ioctl for device
[2020/09/08 22:47:03] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:47:04] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:47:18] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:47:19] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:47:33] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:47:34] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:47:48] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:47:49] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:48:03] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:48:04] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:48:18] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:48:19] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:48:33] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:48:34] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:48:48] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:48:49] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:49:03] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:49:04] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:49:18] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable
[2020/09/08 22:49:19] [error] [src/flb_upstream.c:356 errno=11] Resource temporarily unavailable

Once I downgrade back to v1.5.4, I don’t see these “Resource temporarily unavailable” errors but I still see “Inappropriate ioctl for device”.

While on v1.5.5, I turned on debug mode and got some related logs:

[2020/09/08 22:45:15] [debug] [input:tail:myfile.tail] inode=25194448 events: IN_MODIFY
[2020/09/08 22:45:15] [debug] [input:tail:qa02_uswest2.kubernetes.tail] inode=25194448 events: IN_MODIFY
[2020/09/08 22:45:15] [debug] [task] created task=0x7f6c93ab2540 id=0 without routes, dropping.
[2020/09/08 22:45:15] [debug] [task] destroy task=0x7f6c93ab2540 (task_id=0)
[2020/09/08 22:45:15] [debug] [task] created task=0x7f6c93ab2540 id=0 without routes, dropping.
[2020/09/08 22:45:15] [debug] [task] destroy task=0x7f6c93ab2540 (task_id=0)
[2020/09/08 22:45:15] [debug] [task] created task=0x7f6c93ab2540 id=0 OK
[2020/09/08 22:45:15] [error] [src/flb_upstream.c:356 errno=25] Inappropriate ioctl for device
[2020/09/08 22:45:15] [debug] [upstream] KA connection #23 is in a failed state to: logging.googleapis.com:443, cleaning up
[2020/09/08 22:45:16] [debug] [output:stackdriver:stackdriver.0] HTTP Status=200
[2020/09/08 22:45:16] [debug] [upstream] KA connection #23 to logging.googleapis.com:443 is now available

Looking at the GCP Cloud Log API stats, I am only sending 20 logs per second.

@angulito @PettitWesley the valgrind output suggests that indeed we’re looking at the same issue that we’re trying to solve here: https://github.com/fluent/fluent-bit/pull/2507. That PR is still trying to get at the root cause; we’re obviously trying to free memory with a bad pointer, and it definitely seems to be a product of destroying that connection twice and how we have lingering events in the event queue that should be purged. It seems like the discussion is definitely going places, thank you @PettitWesley 🙇

Let me know if I can help in any way.

@angulito Here it is:

FROM amazon/aws-for-fluent-bit:latest
RUN yum -y install  valgrind
ENTRYPOINT valgrind /fluent-bit/bin/fluent-bit  -c /fluent-bit/etc/fluent-bit.conf

If you can catch the crash with this, Valgrind will tell you where in the code it originated from.

I set up 2 FireLens tasks with datadog outputs last night to try to repro this. One is just the latest AWS for Fluent bit image, one is a custom image built with the valgrind tool, which should help diagnose the segfault if it can be reproduced.