Fluentd application logs are not captured by either <match fluent.*> and <label @FLUENT_LOG> when SIGUSR2 signal is triggered.

DhanushAmbig commented 3 months ago

Describe the bug

I've installed Fluentd installed with provided below configuration and applying filters to Fluentd application's own logs. We have a usecase to reload configuration when needed, to achieve this we are using SIGUSR2 signal for graceful reload. When SIGUSR2 signal is sent to supervisor fluentd process and configuration is reloaded the and <label @FLUENT_LOG> are not able to capture the fluentd application's own logs. Is this a known issue/limitation. Please suggest if there is anyway to overcome this.

To Reproduce

Deploy fluentd with provided configuration.
Send SIGUSR2 signal to fluentd supervisor process.

Expected behavior

After reload, the fluentd own logs should get captured by "label @FLUENT_LOG" and should come in desired json format.

Your Environment

- Fluentd version: 1.16.3
- Fluent Package version: 5.0.2-1

Your Configuration

<system>
  <log>
    format json
    time_format %Y-%m-%dT%H:%M:%S%z
  </log>
</system>

<source>
  @type tail
  path /var/log/containers/*.log
  read_from_head true
  pos_file /var/log/fluentd-container-log.pos
  tag kubernetes.*
  <parse>
    @type json
  </parse>
</source>

<filter kubernetes.**>
  @type kubernetes_metadata
  kubernetes_url https://kubernetes.default.svc:443
</filter>

<match kubernetes.**>
  @type null
</match>

<label @FLUENT_LOG>
  <filter fluent.*>
    @type record_transformer
    enable_ruby true
    renew_record true
    <record>
      log ${ { message: record["message"]  } }
      type "log"
      time ${record.has_key?("time") ? record["time"]: time.strftime('%Y-%m-%dT%H:%M:%S%z') }
    </record>
  </filter>
  <match fluent.*>
    @type stdout
    <format>
      @type json
    </format>
  </match>
</label>

Your Error Log

Logs before sending SIGUSR2 signal:
{"time":"2024-05-17T06:33:53+0000","level":"info","message":"stats - namespace_cache_size: 7, pod_cache_size: 3, pod_cache_watch_updates: 1, namespace_cache_api_updates: 2, pod_cache_api_updates: 2, id_cache_miss: 2, pod_cache_host_updates: 3, namespace_cache_host_updates: 7","worker_id":0}
{"log":{"message":"stats - namespace_cache_size: 7, pod_cache_size: 3, pod_cache_watch_updates: 1, namespace_cache_api_updates: 2, pod_cache_api_updates: 2, id_cache_miss: 2, pod_cache_host_updates: 3, namespace_cache_host_updates: 7"},"type":"log","time":"2024-05-17T06:33:53+0000"}

Logs after sending SIGUSR2 signal:
{"time":"2024-05-17T06:35:32+0000","level":"info","message":"stats - namespace_cache_size: 7, pod_cache_size: 3, namespace_cache_api_updates: 2, pod_cache_api_updates: 2, id_cache_miss: 2, pod_cache_host_updates: 3, namespace_cache_host_updates: 7","worker_id":0}

Additional context

Before reload: fluentd logs were seen twice ie. once generated from the application and second time getting captured using fluentd configuration and getting filtered using label @FLUENT_LOG. After reload: Fluentd logs are seen only once i.e. being generated by the application and not getting captured by fluentd config.

Quick help would be appreciated. Thanks in advance. No response

kenhys commented 1 month ago

I've checked with more simple case:

<system>
  <log>
    format json
    time_format %Y-%m-%dT%H:%M:%S%z
  </log>
</system>

<source>
  @type sample
  tag sample
</source>

<match sample>
  @type null
</match>

<label @FLUENT_LOG>
  <filter fluent.*>
    @type record_transformer
    enable_ruby true
    renew_record true
    <record>
      log ${ { message: record["message"]  } }
      type "log"
      time ${record.has_key?("time") ? record["time"]: time.strftime('%Y-%m-%dT%H:%M:%S%z') }
    </record>
  </filter>
  <match fluent.*>
    @type stdout
    <format>
      @type json
    </format>
  </match>
</label>

Here is the outcome:

After emitting USR2 signal {"time":"2024-07-09T14:05:17+0900","level":"info","message":"Reloading new config"} {"time":"2024-07-09T14:05:17+0900","level":"warn","message":"both of Plugin @id and path for are not specified. Using on-memory store."} {"time":"2024-07-09T14:05:17+0900","level":"warn","message":"both of Plugin @id and path for are not specified. Using on-memory store."} {"time":"2024-07-09T14:05:17+0900","level":"info","message":"using configuration file: \n \n \n format json\n time_format %Y-%m-%dT%H:%M:%S%z\n \n \n \n @type sample\n tag \"sample\"\n \n \n @type null\n \n \n \n @type record_transformer\n enable_ruby true\n renew_record true\n \n log ${ { message: record[\"message\"] } }\n type log\n time ${record.has_key?(\"time\") ? record[\"time\"]: time.strftime('%Y-%m-%dT%H:%M:%S%z') }\n \n \n \n @type stdout\n \n @type \"json\"\n \n \n \n"} {"time":"2024-07-09T14:05:17+0900","level":"info","message":"shutting down input plugin type=:sample plugin_id=\"object:bb8\""} {"time":"2024-07-09T14:05:17+0900","level":"info","message":"shutting down filter plugin type=:record_transformer plugin_id=\"object:b54\""} {"time":"2024-07-09T14:05:17+0900","level":"info","message":"shutting down output plugin type=:stdout plugin_id=\"object:b68\""} {"time":"2024-07-09T14:05:17+0900","level":"info","message":"shutting down output plugin type=:null plugin_id=\"object:b90\""} {"time":"2024-07-09T14:05:17+0900","level":"info","message":"adding filter in @FLUENT_LOG pattern=\"fluent.*\" type=\"record_transformer\""} {"log":{"message":"adding filter in @FLUENT_LOG pattern=\"fluent.*\" type=\"record_transformer\""},"type":"log","time":"2024-07-09T14:05:17+0900"} {"time":"2024-07-09T14:05:17+0900","level":"info","message":"adding match in @FLUENT_LOG pattern=\"fluent.*\" type=\"stdout\""} {"time":"2024-07-09T14:05:17+0900","level":"info","message":"adding match pattern=\"sample\" type=\"null\""} {"log":{"message":"adding match in @FLUENT_LOG pattern=\"fluent.*\" type=\"stdout\""},"type":"log","time":"2024-07-09T14:05:17+0900"} {"log":{"message":"adding match pattern=\"sample\" type=\"null\""},"type":"log","time":"2024-07-09T14:05:17+0900"} {"time":"2024-07-09T14:05:17+0900","level":"info","message":"adding source type=\"sample\""} {"time":"2024-07-09T14:05:17+0900","level":"warn","message":"both of Plugin @id and path for are not specified. Using on-memory store.","worker_id":0} {"log":{"message":"adding source type=\"sample\""},"type":"log","time":"2024-07-09T14:05:17+0900"} {"time":"2024-07-09T14:05:17+0900","level":"warn","message":"both of Plugin @id and path for are not specified. Using on-memory store.","worker_id":0} {"log":{"message":"both of Plugin @id and path for are not specified. Using on-memory store."},"type":"log","time":"2024-07-09T14:05:17+0900"} {"log":{"message":"both of Plugin @id and path for are not specified. Using on-memory store."},"type":"log","time":"2024-07-09T14:05:17+0900"} {"time":"2024-07-09T14:05:17+0900","level":"info","message":"shutting down fluentd worker worker=0","worker_id":0} {"time":"2024-07-09T14:05:17+0900","level":"info","message":"shutting down input plugin type=:sample plugin_id=\"object:94c\"","worker_id":0} {"time":"2024-07-09T14:05:17+0900","level":"info","message":"shutting down filter plugin type=:record_transformer plugin_id=\"object:8e8\"","worker_id":0} {"time":"2024-07-09T14:05:17+0900","level":"info","message":"shutting down output plugin type=:stdout plugin_id=\"object:8fc\"","worker_id":0} {"time":"2024-07-09T14:05:17+0900","level":"info","message":"shutting down output plugin type=:null plugin_id=\"object:924\"","worker_id":0} {"time":"2024-07-09T14:05:17+0900","level":"info","message":"restart fluentd worker worker=0","worker_id":0}

<label @FLUENT_LOG> seems working as expected. It may depend on environment or timing?

need to try reporter's config.

github-actions[bot] commented 2 weeks ago

This issue has been automatically marked as stale because it has been open 30 days with no activity. Remove stale label or comment or this issue will be closed in 7 days

github-actions[bot] commented 1 week ago

This issue was automatically closed because of stale in 7 days

fluent / fluentd