[Q&A] issues with file buffer after upgrading to 1.16.4

[larntz]

What is a problem?

Since upgrading to 1.16.4 we've seen a large increase in the [warn] message below. I am trying to determine why this has increased, and if it's a problem.

In

fluentd/lib/fluent/plugin/buffer/file_chunk.rb

Line 69 in eac830f

write_metadata # this should be at first: of course, this operation may fail

I see there is a comment that says this operation may fail.

Can anyone tell me what the impact of this might be? Are logs lost, or is something benign failing, and this can be ignored?

Describe the configuration of Fluentd

<worker 0>
<source>
  @type s3
  @log_level debug
  s3_bucket s3-bucket-for-access-logs
  s3_region "#{ENV['AWS_REGION']}"
  add_object_metadata true
  store_as gzip_command
  <sqs>
    queue_name s3-queue-redacted
  </sqs>
  @label AWS_LB_ACCESS
  tag aws-lb-access
</source>
</worker>

<label AWS_LB_ACCESS>

  <filter **>
    @type prometheus
    @id prometheus_count_es_alb_incoming_by_tag
    <metric>
      name fluentd_input_status_num_records_total
      type counter
      desc The total number of incoming records
    </metric>
  </filter>

  <filter aws-lb-access>
    @type parser
    @id aws-lb-access-log-grok
    reserve_time true
    reserve_data false
    key_name message
    remove_key_name_field true
    <parse>
      @type grok
      grok_failure_key grokfailure
      custom_pattern_path /fluentd/patterns/aws
      # nlb access logs
      <grok>
        pattern %{NLBLOG}
        grok_pattern_series ecs-v1
        time_key timestamp
        keep_time_key
      </grok>
      # alb access logs
      <grok>
        pattern %{ALBLOG}
        grok_pattern_series ecs-v1
        time_key timestamp
        keep_time_key
      </grok>
      # classic lb tcp logs
      <grok>
        pattern %{ELBTCPLOG}
        grok_pattern_series ecs-v1
        time_key timestamp
        keep_time_key
      </grok>
      # classib lb http logs
      <grok>
        pattern %{ELBHTTPLOG}
        grok_pattern_series ecs-v1
        time_key timestamp
        keep_time_key
      </grok>
    </parse>
  </filter>

  <filter aws-lb-access>
    @type record_modifier
    @id add_timestamp_field_es_elb_access
    <record>
      @timestamp ${record["timestamp"]}
    </record>
  </filter>

  <filter aws-lb-access>
    @type parser
    @id aws-lb-access-url-fields
    reserve_time true
    reserve_data true
    key_name uri_original
    remove_key_name_field false
    <parse>
      @type grok
      grok_failure_key grokfailure
      # nlb access logs
      <grok>
        pattern %{GREEDYDATA}://(?:internal-)%{GREEDYDATA:cluster_name}(?:-alb-datanodes)%{GREEDYDATA}:9200\/((?<index_name>account_[0-9]*_[0-9]*)/)?(?:[\/])?(?<handler_name>(_[^\/\?]+)?)\??%{GREEDYDATA:additional_params}
        time_key timestamp
        keep_time_key
      </grok>
    </parse>
  </filter>

  # ensure each record has it's _id set to a unique hash
  # this prevents duplicate records when bulk requests are retried
  <filter **>
    @type elasticsearch_genid
    hash_id_key _hash
    use_record_as_seed true
    use_entire_record true
  </filter>

  <filter aws-lb-access>
    @type record_modifier
    @id_es_alb_access_log_add_hostname
    <record>
      fluentd_pod "#{Socket.gethostname}"
    </record>
  </filter>

  <match aws-lb-access>
    @type copy
    <store>
      @type prometheus
      @id prometheus_es_alb_output_records_count
      <metric>
        name fluentd_output_status_es_alb_access_num_records_total
        type counter
        desc The total number of outgoing records
        <labels>
          input_role aws-lb-access-logs
        </labels>
      </metric>
    </store>
    <store>
  #  bulk_message_request_threshold + chunk_limit_size + 16k <= actual_message_size_limit
    @type elasticsearch
    @id es_alb_logs_output
    @log_level warn
    id_key _hash
    remove_keys _hash
    # data streams require using create instead of index. create calls require that the _id field already exist
    write_operation create
    log_es_400_reason true
    http_backend typhoeus
    include_timestamp true # https://github.com/uken/fluent-plugin-elasticsearch#include_timestamp
    hosts "#{ENV['ES_LOGS_HOSTS']}"
    port 9200
    user "#{ENV['ES_LOGS_USER']}"
    password "#{ENV['ES_LOGS_PASSWORD']}"
    suppress_type_name true
    ssl_verify true
    scheme https
    ca_file /mnt/secrets-store/es_ca_cert
    index_name logs-stream
    bulk_message_request_threshold 16MB
    request_timeout "#{ENV['ES_REQUEST_TIMEOUT']}"
    retry_tag 'retry_es'
    reload_on_failure true
    compression_level default_compression
    slow_flush_log_threshold 60.0
    <buffer tag, cluster_name, time>
      @type file
      timekey 2s
      timekey_wait 0
      # https://docs.fluentd.org/buffer#handling-unrecoverable-errors
      disable_chunk_backup true
      chunk_full_threshold 0.9
      chunk_limit_size 16MB
      flush_mode interval
      flush_interval 5s
      flush_thread_count "#{ENV['ES_ALB_ACCESS_LOG_FLUSH_THREAD_COUNT']}"
      retry_wait 90s
      retry_timeout 1h
    </buffer>
    </store>
  </match>
</label>

Describe the logs of Fluentd

fluentd-0 fluentd 2024-03-25 17:30:52 +0000 [warn]: #1 send an error event stream to @ERROR: error_class=IOError error="closed stream" location="/usr/local/lib/ruby/gems/3.2.0/gems/fluentd-1.16.4/lib/fluent/plugin/buffer/file_chunk.rb:257:in `seek'" tag="aws-lb-access"
fluentd-9 fluentd 2024-03-25 17:31:04 +0000 [warn]: #3 send an error event stream to @ERROR: error_class=IOError error="closed stream" location="/usr/local/lib/ruby/gems/3.2.0/gems/fluentd-1.16.4/lib/fluent/plugin/buffer/file_chunk.rb:257:in `seek'" tag="aws-lb-access"
fluentd-9 fluentd 2024-03-25 17:35:19 +0000 [warn]: #5 send an error event stream to @ERROR: error_class=IOError error="closed stream" location="/usr/local/lib/ruby/gems/3.2.0/gems/fluentd-1.16.4/lib/fluent/plugin/buffer/file_chunk.rb:257:in `seek'" tag="aws-lb-access"
fluentd-11 fluentd 2024-03-25 17:35:21 +0000 [warn]: #5 send an error event stream to @ERROR: error_class=IOError error="closed stream" location="/usr/local/lib/ruby/gems/3.2.0/gems/fluentd-1.16.4/lib/fluent/plugin/buffer/file_chunk.rb:257:in `seek'" tag="aws-lb-access"
fluentd-7 fluentd 2024-03-25 17:35:34 +0000 [warn]: #3 send an error event stream to @ERROR: error_class=IOError error="closed stream" location="/usr/local/lib/ruby/gems/3.2.0/gems/fluentd-1.16.4/lib/fluent/plugin/buffer/file_chunk.rb:257:in `seek'" tag="aws-lb-access"
fluentd-2 fluentd 2024-03-25 17:35:48 +0000 [warn]: #2 send an error event stream to @ERROR: error_class=IOError error="closed stream" location="/usr/local/lib/ruby/gems/3.2.0/gems/fluentd-1.16.4/lib/fluent/plugin/buffer/file_chunk.rb:257:in `seek'" tag="aws-lb-access"
fluentd-2 fluentd 2024-03-25 17:40:32 +0000 [warn]: #2 send an error event stream to @ERROR: error_class=IOError error="closed stream" location="/usr/local/lib/ruby/gems/3.2.0/gems/fluentd-1.16.4/lib/fluent/plugin/buffer/file_chunk.rb:257:in `seek'" tag="aws-lb-access"
fluentd-2 fluentd 2024-03-25 17:40:49 +0000 [warn]: #1 send an error event stream to @ERROR: error_class=IOError error="closed stream" location="/usr/local/lib/ruby/gems/3.2.0/gems/fluentd-1.16.4/lib/fluent/plugin/buffer/file_chunk.rb:257:in `seek'" tag="aws-lb-access"

Environment

- Fluentd version: 1.16.4
- Operating system: Linux
- Kernel version: 6.1.77

[daipom]

Thanks for your report.

There is a possibility that #4342 has some impact.
I will check it.

Can anyone tell me what the impact of this might be? Are logs lost, or is something benign failing, and this can be ignored?

This warning means that some data was sent to @ERROR label.
So, there is a possibility that some data was not sent to where it really needs to be sent.

[daipom]

@larntz Do you have full stack traces? If you have, could you share them?

fluentd-0 fluentd 2024-03-25 17:30:52 +0000 [warn]: #1 send an error event stream to @ERROR: error_class=IOError error="closed stream" location="/usr/local/lib/ruby/gems/3.2.0/gems/fluentd-1.16.4/lib/fluent/plugin/buffer/file_chunk.rb:257:in `seek'" tag="aws-lb-access"

[ashie]

We found a possible cause of this issue due to missing lock in #4342.
I created a new issue as #4446 from this article.
Thanks for your report!

[larntz]

Thank you! I can provide stack traces if you need them, but I am not sure what the best way to collect one would be. Please let me know what if any information you will need from me (sounds like ashie may have already found the issue).

Btw, you all are fantastic. This is the second time I've reported an issue and within a day you identified the cause. It is greatly appreciated!

[daipom]

@larntz Thanks! Now, we are trying to fix the problem that may have caused this warning in the following:

• buffer: fix emit error of race condition #4447

I can provide stack traces if you need them, but I am not sure what the best way to collect one would be. Please let me know what if any information you will need from me (sounds like ashie may have already found the issue).

Can you check the logs around this warning log in Fluentd's log files?
Do you see a stack trace there?

[larntz]

I do not see any stack traces in our logs. Only the lines I posted earlier.

[daipom]

@larntz We have released v1.16.5 to fix this.
Sorry to trouble you, but we'd appreciate it if you could upgrade to v1.16.5 and see if it fixes the problem.

[ashie]

We'll release also Docker image later.

[larntz]

I'll work on upgrading today when the docker image is released and let you know if this is resolved. Thanks so much for working on this so quickly!

[larntz]

I deployed 1.16.5 a few hours ago and haven't seen the closed stream error since. It was happening quite a lot so I think this is fixed.

Thanks again for your quick work on this!

[daipom]

Thanks for confirming!
We are glad this issue has been fixed!

Thanks so much for your report!
Please let us know if you have a problem again!