[bug] Adding plugin ID suppress all plugin logs

[kmotrebski]

TL;DR

Adding @id option to any plugin configuration makes Fluentd logs to be suppressed. Fluentd logs are not delivered into output plugins. Can be replicated within seconds - I've added small Docker Compose project.

This is quite important problem as I want to add plugin IDs to track Fluentd metrics and logs. This behaviour makes tracking errors and metrics impossible.

Basic info:

• Fluentd version: v1.3.2-1.0 (latest Docker image)
• replicated on latest edge (v1.3.2-1.0) and edge-debian (v1.3.2-debian-1.0) Docker images.
• Docker 17.05.0-ce, build 89658be
• Docker Compose: version 1.20.1, build 5d8c71b
• OS: Lubuntu 14.04, specifically: 4.4.0-66-generic #87-Ubuntu SMP Fri Mar 3 15:29:05 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

My configuration

Full configuration needed to replicate below. I've uploaded it here too.

<source>
  @type tcp
  #assigning plugin id makes Fluentd to supress its own logs against plugins
  @id awesome_source_id
  tag sth_awesome
  port 5170
  bind 0.0.0.0
  <parse>
    @type regexp
    expression /^(?<field1>\d+):(?<field2>\w+)$/
  </parse>
</source>

#logs data streamed via tcp into file
<match sth_awesome.**>
  @type file
  path /tmp/logs/sth_awesome
  <buffer>
      timekey_wait 1s
  </buffer>
</match>

#should log Fluentd internal logs into file but it does NOT
<match fluent.**>
  @type file
  path /tmp/logs/fluentd
  <buffer>
      timekey_wait 1s
  </buffer>
</match>

So the configuration is consisting of:

• 1x TCP data source
• 1x output for orginal events sent via TCP
• 1x output for any potential Fluentd logs, errors

Replication

So let's stream via TCP invalid_string string:

echo 'invalid_string' | netcat localhost 5170

This should cause an error. I properly see error in docker logs:

2018-12-31 14:20:27 +0000 [warn]: #0 [awesome_source_id] pattern not match message="invalid_string"

So error is visible in Docker logs but is not streamed into a /tmp/logs/fluentd as configuration says. However, when I remove @id awesome_source_id part from output configuration then everything works properly. The following is then streamed into the file too:

2018-12-31T14:36:37+00:00	fluent.warn	{"message":"pattern not match message=\"invalid_string\""}

Problem

I want to track Fluentd errors and metrics. I want to have plugin ID visible so I know what is what. This behaviour makes tracking errors and metrics very difficult.

Scope

Happens for many plugins. At least: in forward, out elasticsearch, filter parser, out file, record_transformer. In this configuration I am streaming everything into a file but in my production use I am streaming it into Elasticsearch. That is why I think it is not a matter of any plugin but rather Fluentd itself.

Replication with Docker

Can be replicated using Docker within a few seconds. You can find the project to help with replication here: https://github.com/kmotrebski/random/tree/master/20181231_fluentd_suppressing_internal_logs_problem

Just copy&paste:

git clone [email protected]:kmotrebski/random.git kmo_bug
cd kmo_bug/20181231_fluentd_suppressing_internal_logs_problem/
./reproducing.sh

You will see that no errors are added to the logs/fluentd. But if you comment ID declaration:

#@id awesome_source_id

and try again by ./reproducing.sh you will see that errors are properly added to the file.

[repeatedly]

I confirmed the issue. Now investigating.

[repeatedly]

Okay, I found the cause.

[repeatedly]

Patch is here: #2252

[kmotrebski]

@repeatedly Awesome, thanks a lot!

As far as I see the CI/CD is failing, can I still install this patched version and use or it is not going to work? If not then when is expected this commit to be released officially?

Also, is a way I have created this report helpful or it is not worth it to create this Docker snippet etc?

[kmotrebski]

@repeatedly I've managed to build Fluentd from source (commit with your patch #2252) and then build Docker image. I can confirm that bug is no longer there on this version.

When is expected you patch will be merged and officially released?

Edit: I've built it using this commit: 1cc9b27 so it does not include the latest commit of yours in this pull request (at least 1 at the time of writing this comment).

[repeatedly]

Thanks for the testing!

We need review for the patch from other developers before merge.
It will be done at the beginning of the week.

[kmotrebski]

@repeatedly When is expected the docker images to be updated? I mean that image for v1.3.3 version will be published?

[repeatedly]

I'm now working on td-agent 3.3.0 release. After that, I will work on it.
Sorry, I have some important tasks so several tasks are delayed...

[kmotrebski]

@repeatedly I think there is some bigger problem with the Fluentd internal logs. It does not work as expected.

I have found another log that is suppressed: https://github.com/fluent/fluentd/blob/v1.3.3/lib/fluent/supervisor.rb#L124-L125

I've tested it on newest version (after your patch from this issue), that is v1.3.3 version.

Problem is the same. Logs are visible in docker logs:

2019-01-10 15:40:09 +0000 [debug]: fluent/log.rb:302:debug: fluentd RPC got /api/config.dump request
2019-01-10 15:40:09 +0000 [info]: fluent/log.rb:322:info: get dump in-memory config via HTTP

...but does not reach any plugin, hence it's impossible to actually log this records.

Added following to my configuration:

<system>
  rpc_endpoint 0.0.0.0:24444
  log_level debug
  enable_get_dump true
</system>

Action I do is:

curl -XGET localhost:24444/api/config.getDump

Should I expand my "reproducing" snippet with Docker that I've prepared before?

[repeatedly]

Above logs are generated in supervisor, not worker.
Supervisor manages workers and supervisor itself doesn't have plugins so impossible to capture like other logs.