Fluentd does not send fluentd.** events from a part of plugin_id configured plugins.

result.md

Occured fact

• A part of plugin_id configured plugins do not send fluentd.** events

Confirm environment

• OS: CentOS Linux release 7.3.1611
• Fluentd: v1.0.2(From td-agent 3.1.1)

Confirm Pattern

I confirmed below setting for capturing fluent.** events.

<label @FLUENT_LOG>
  <filter fluent.**>
    @type stdout
  </filter>
</label>

Plugin uses grobal variable $log, plugin_id configured.

setting

<source>
  @type          tail
  @id            analyze_logs_tail
  path           /var/log/analyze_logs_%Y-%m-%d_%H.log
  pos_file       /var/log/td-agent/pos/analyze_logs.pos
  <parse>
    @type       ltsv
    time_key    time
    time_format %Y-%m-%dT%H:%M:%S%z
  </parse>
  read_from_head true
  tag            analyze.logs
</source>

log output point

https://github.com/fluent/fluentd/blob/v1.0.2/lib/fluent/plugin/in_tail.rb#L286

$log.warn "#{path} not found. Continuing without tailing it."

output log

2018-03-07 12:00:12 +0900 [warn]: /var/log/analyze_logs_2018-03-07_12.log not found. Continuing without tailing it.

output event

2018-03-07 12:00:12.000000000 +0900 fluent.warn: {"message":"/var/log/analyze_logs_2018-03-07_12.log not found. Continuing without tailing it."}

Plugin uses grobal variable $log, plugin_id not configured.

setting

<source>
  @type          tail
  path           /var/log/analyze_logs_%Y-%m-%d_%H.log
  pos_file       /var/log/td-agent/pos/analyze_logs.pos
  <parse>
    @type       ltsv
    time_key    time
    time_format %Y-%m-%dT%H:%M:%S%z
  </parse>
  read_from_head true
  tag            analyze.logs
</source>

output log

2018-03-07 13:00:12 +0900 [warn]: /var/log/analyze_logs_2018-03-07_13.log not found. Continuing without tailing it.

output event

2018-03-07 13:00:12.000000000 +0900 fluent.warn: {"message":"/var/log/analyze_logs_2018-03-07_13.log not found. Continuing without tailing it."}

Plugin uses log(From PluginLoggerMixin), plugin_id configured.

log output point

https://github.com/fluent/fluentd/blob/v1.0.2/lib/fluent/plugin/output.rb#L1151

log.warn msg, retry_time: @retry.steps, next_retry_seconds: @retry.next_time, chunk: chunk_id_hex, error: error

setting

<match traffic.**>
  @id forward_traffic_logs_to_manage_server
  @type forward
  require_ack_response true
  <buffer tag>
    @type "memory"
    flush_interval 1s
    flush_thread_interval 1s
    flush_thread_burst_interval 1s
    retry_forever true
    retry_max_interval 300s
    chunk_limit_size 4m
    queue_limit_length 256
  </buffer>
  <server>
    name "fluentd-test-manage01"
    host "192.168.100.90"
    port 24224
  </server>
</match>

output log

2018-03-04 08:07:40 +0900 [warn]: [forward_traffic_logs_to_manage_server] failed to flush the buffer. retry_time=0 next_retry_seconds=2018-03-04 08:07:41 +0900 chunk="56669aff8af5af1eb20fad8582ecdd8e" error_class=Fluent::Plugin::ForwardOutput::NoNodesAvailable error="no nodes are available"

output event

• no output

Plugin uses log(From PluginLoggerMixin), plugin_id not configured.

setting

<match traffic.**>
  @type forward
  require_ack_response true
  <buffer tag>
    @type "memory"
    flush_interval 1s
    flush_thread_interval 1s
    flush_thread_burst_interval 1s
    retry_forever true
    retry_max_interval 300s
    chunk_limit_size 4m
    queue_limit_length 256
  </buffer>
  <server>
    name "fluentd-test-manage01"
    host "192.168.100.90"
    port 24224
  </server>
</match>

output log

2018-03-12 17:56:21 +0900 [warn]: failed to flush the buffer. retry_time=0 next_retry_seconds=2018-03-12 17:56:21 +0900 chunk="5673350ac6797484a1e21e595f0456fb" error_class=Errno::ECONNREFUSED error="Connection refused - connect(2) for \"192.168.100.90\" port 24224"

output event

2018-03-12 17:56:21.190575774 +0900 fluent.warn: {"retry_time":0,"next_retry_seconds":"2018-03-12 17:56:21 +0900","chunk":"5673350ac6797484a1e21e595f0456fb","error":"#<Errno::ECONNREFUSED: Connection refused - connect(2) for \"10.26.206.90\" port 24224>","message":"failed to flush the buffer. retry_time=0 next_retry_seconds=2018-03-12 17:56:21 +0900 chunk=\"5673350ac6797484a1e21e595f0456fb\" error_class=Errno::ECONNREFUSED error=\"Connection refused - connect(2) for \\\"192.168.100.90\\\" port 24224\""}

Source confirm result.

It seems when plugin_id configured, fluentd does't push fluent.** event through PluginLoggerMixin.

Fluentd initialization flow (standalone worker)

• 1. RootAgent configured
  • https://github.com/fluent/fluentd/blob/v1.0.2/lib/fluent/engine.rb#L131
  • In RootAgent configure, plugins are configured.
    • When plugin_id configured, PluginLogger uses $log.dup. ($log is not called enable_event)
    • https://github.com/fluent/fluentd/blob/v1.0.2/lib/fluent/log.rb#L573
• 2. $log enable_event called.
  • https://github.com/fluent/fluentd/blob/v1.0.2/lib/fluent/engine.rb#L161

Log event push condition

• If enable_event called, $log push log event(fluent.**).

  • https://github.com/fluent/fluentd/blob/v1.0.2/lib/fluent/log.rb#L476

• It seems PluginLogger's $log.dup is not called enable_event, so PluginLogger does not push log event(fluent.**).

How should be?

• Should plugin_id configured PluginLogger push log event(fluent.**)?

  • If so, what format? plugin_id contain?

• Which should each plugins uses $log or log?
   - What reason logger are used differently?