Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Buffer: v1.16.4: Emit error by IOError #4446

Closed
ashie opened this issue Mar 26, 2024 Discussed in #4445 · 8 comments · Fixed by #4447
Closed

Buffer: v1.16.4: Emit error by IOError #4446

ashie opened this issue Mar 26, 2024 Discussed in #4445 · 8 comments · Fixed by #4447
Labels
bug Something isn't working
Milestone
v1.16.5

Comments

@ashie
Copy link
Member

ashie commented Mar 26, 2024

Discussed in #4445

Originally posted by larntz March 26, 2024

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
@ashie ashie added the bug Something isn't working label Mar 26, 2024
@daipom daipom changed the title Issues with file buffer after upgrading to 1.16.4 Buffer: v1.16.4: Emit error by IOError due to race conditions Mar 26, 2024
@ashie
Copy link
Member Author

ashie commented Mar 26, 2024

In #4342 we changed the code related to this.
Although we aren't sure yet whether it's the cause of this issue or not, #4342 obviously lacks mutex lock until block.call is called for chunks. We need to fix it.

@daipom daipom mentioned this issue Mar 26, 2024
Merged
@daipom daipom changed the title Buffer: v1.16.4: Emit error by IOError due to race conditions Buffer: v1.16.4: Emit error by IOError Mar 27, 2024
@daipom
Copy link
Contributor

daipom commented Mar 27, 2024 •
edited
Loading

I cannot deny the possibility of other unexpected causes, but, at least, #4342 's lack of lock can cause race condition and emit error.
(Because the staged chunk being handled in Buffer:write can be flushed and purged by the flush thread, although I haven't confirmed it in the actual behavior yet.)

I can't find any other cause for the emit error since v1.16.4.
So, at this time, I assume this race condition is the cause, and it will be fixed by #4447.

@daipom daipom mentioned this issue Mar 27, 2024
Merged
@daipom daipom added this to the v1.16.5 milestone Mar 27, 2024
@daipom
Copy link
Contributor

daipom commented Mar 27, 2024 •
edited
Loading

(Because the staged chunk being handled in Buffer:write can be flushed and purged by the flush thread, although I haven't confirmed it in the actual behavior yet.)

I have reproduced this issue using the following config with v1.16.4.
And, this does not reproduce with v1.16.3 or after #4447.

<source>
  @type sample
  tag test
  size 10000
</source>

<source>
  @type sample
  tag test
  size 50000
</source>

<source>
  @type sample
  tag test
  size 100000
</source>

<match test.**>
  @type null
  <buffer tag, time>
    @type file
    path /test/fluentd/buffer/
    flush_thread_count 2
    timekey 2s
    timekey_wait 0
    flush_mode interval
    flush_interval 3s
    chunk_limit_size 1MB
    chunk_full_threshold 0.9
    overflow_action drop_oldest_chunk
  </buffer>
</match>

Fluentd logs:

2024-03-27 16:39:43 +0900 [info]: #0 fluentd worker is now running worker=0
2024-03-27 16:39:44 +0900 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 1350000bytes
2024-03-27 16:39:44 +0900 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 2700000bytes
2024-03-27 16:39:44 +0900 [warn]: #0 emit transaction failed: error_class=IOError error="not opened for writing" location="/home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:258:in `write'" tag="test"
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:258:in `write'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:258:in `write_metadata'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:69:in `commit'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer.rb:377:in `write'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:1069:in `block in handle_stream_with_standard_format'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:977:in `write_guard'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:1068:in `handle_stream_with_standard_format'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:971:in `execute_chunking'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:897:in `emit_buffered'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/event_router.rb:115:in `emit_stream'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/event_router.rb:111:in `emit_array'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:110:in `block in emit'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:109:in `times'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:109:in `emit'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:98:in `run'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2024-03-27 16:39:45 +0900 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 2700000bytes
2024-03-27 16:39:45 +0900 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 1350000bytes
2024-03-27 16:39:45 +0900 [warn]: #0 emit transaction failed: error_class=IOError error="closed stream" location="/home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:257:in `seek'" tag="test"
  2024-03-27 16:39:45 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:257:in `seek'
  2024-03-27 16:39:45 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:257:in `write_metadata'
  2024-03-27 16:39:45 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:69:in `commit'
  2024-03-27 16:39:45 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer.rb:377:in `write'
  2024-03-27 16:39:45 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:1069:in `block in handle_stream_with_standard_format'
  2024-03-27 16:39:45 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:977:in `write_guard'
  2024-03-27 16:39:45 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:1068:in `handle_stream_with_standard_format'
  2024-03-27 16:39:45 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:971:in `execute_chunking'
  2024-03-27 16:39:45 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:897:in `emit_buffered'
  2024-03-27 16:39:45 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/event_router.rb:115:in `emit_stream'
  2024-03-27 16:39:45 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/event_router.rb:111:in `emit_array'
  2024-03-27 16:39:45 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:110:in `block in emit'
  2024-03-27 16:39:45 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:109:in `times'
  2024-03-27 16:39:45 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:109:in `emit'
  2024-03-27 16:39:45 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:98:in `run'
  2024-03-27 16:39:45 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2024-03-27 16:39:46 +0900 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 1350000bytes
2024-03-27 16:39:46 +0900 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 2700000bytes
2024-03-27 16:39:46 +0900 [warn]: #0 emit transaction failed: error_class=IOError error="closed stream" location="/home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:257:in `seek'" tag="test"
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:257:in `seek'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:257:in `write_metadata'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:69:in `commit'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer.rb:377:in `write'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:1069:in `block in handle_stream_with_standard_format'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:977:in `write_guard'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:1068:in `handle_stream_with_standard_format'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:971:in `execute_chunking'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:897:in `emit_buffered'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/event_router.rb:115:in `emit_stream'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/event_router.rb:111:in `emit_array'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:110:in `block in emit'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:109:in `times'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:109:in `emit'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:98:in `run'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2024-03-27 16:39:47 +0900 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 1350000bytes
2024-03-27 16:39:47 +0900 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 2700000bytes
2024-03-27 16:39:48 +0900 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 1350000bytes
2024-03-27 16:39:48 +0900 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 270000bytes
2024-03-27 16:39:48 +0900 [warn]: #0 emit transaction failed: error_class=IOError error="not opened for writing" location="/home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:258:in `write'" tag="test"
  2024-03-27 16:39:48 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:258:in `write'
  2024-03-27 16:39:48 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:258:in `write_metadata'
  2024-03-27 16:39:48 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:69:in `commit'
  2024-03-27 16:39:48 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer.rb:377:in `write'
  2024-03-27 16:39:48 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:1069:in `block in handle_stream_with_standard_format'
  2024-03-27 16:39:48 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:977:in `write_guard'
  2024-03-27 16:39:48 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:1068:in `handle_stream_with_standard_format'
  2024-03-27 16:39:48 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:971:in `execute_chunking'
  2024-03-27 16:39:48 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:897:in `emit_buffered'
  2024-03-27 16:39:48 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/event_router.rb:115:in `emit_stream'
  2024-03-27 16:39:48 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/event_router.rb:111:in `emit_array'
  2024-03-27 16:39:48 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:110:in `block in emit'
  2024-03-27 16:39:48 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:109:in `times'
  2024-03-27 16:39:48 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:109:in `emit'
  2024-03-27 16:39:48 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:98:in `run'
  2024-03-27 16:39:48 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2024-03-27 16:39:48 +0900 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 2700000bytes
2024-03-27 16:39:49 +0900 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 1350000bytes
2024-03-27 16:39:49 +0900 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 2700000bytes
2024-03-27 16:39:49 +0900 [warn]: #0 emit transaction failed: error_class=IOError error="not opened for writing" location="/home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:258:in `write'" tag="test"
  2024-03-27 16:39:49 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:258:in `write'
  2024-03-27 16:39:49 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:258:in `write_metadata'
  2024-03-27 16:39:49 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:69:in `commit'
  2024-03-27 16:39:49 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer.rb:377:in `write'
  2024-03-27 16:39:49 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:1069:in `block in handle_stream_with_standard_format'
  2024-03-27 16:39:49 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:977:in `write_guard'
  2024-03-27 16:39:49 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:1068:in `handle_stream_with_standard_format'
  2024-03-27 16:39:49 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:971:in `execute_chunking'
  2024-03-27 16:39:49 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:897:in `emit_buffered'
  2024-03-27 16:39:49 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/event_router.rb:115:in `emit_stream'
  2024-03-27 16:39:49 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/event_router.rb:111:in `emit_array'
  2024-03-27 16:39:49 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:110:in `block in emit'
  2024-03-27 16:39:49 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:109:in `times'
  2024-03-27 16:39:49 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:109:in `emit'
  2024-03-27 16:39:49 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:98:in `run'
  2024-03-27 16:39:49 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2024-03-27 16:39:50 +0900 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 2700000bytes
2024-03-27 16:39:50 +0900 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 1350000bytes
2024-03-27 16:39:50 +0900 [warn]: #0 emit transaction failed: error_class=IOError error="not opened for writing" location="/home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:258:in `write'" tag="test"
  2024-03-27 16:39:50 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:258:in `write'
  2024-03-27 16:39:50 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:258:in `write_metadata'
  2024-03-27 16:39:50 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:69:in `commit'
  2024-03-27 16:39:50 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer.rb:377:in `write'
  2024-03-27 16:39:50 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:1069:in `block in handle_stream_with_standard_format'
  2024-03-27 16:39:50 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:977:in `write_guard'
  2024-03-27 16:39:50 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:1068:in `handle_stream_with_standard_format'
  2024-03-27 16:39:50 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:971:in `execute_chunking'
  2024-03-27 16:39:50 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:897:in `emit_buffered'
  2024-03-27 16:39:50 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/event_router.rb:115:in `emit_stream'
  2024-03-27 16:39:50 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/event_router.rb:111:in `emit_array'
  2024-03-27 16:39:50 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:110:in `block in emit'
  2024-03-27 16:39:50 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:109:in `times'
  2024-03-27 16:39:50 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:109:in `emit'
  2024-03-27 16:39:50 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:98:in `run'
  2024-03-27 16:39:50 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'

@ashie
Copy link
Member Author

ashie commented Mar 27, 2024

Great!

@daipom
Copy link
Contributor

daipom commented Mar 27, 2024

I confirmed 2 kinds of error

  • emit transaction failed: error_class=IOError error="not opened for writing"
2024-03-27 16:39:44 +0900 [warn]: #0 emit transaction failed: error_class=IOError error="not opened for writing" location="/home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:258:in `write'" tag="test"
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:258:in `write'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:258:in `write_metadata'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:69:in `commit'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer.rb:377:in `write'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:1069:in `block in handle_stream_with_standard_format'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:977:in `write_guard'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:1068:in `handle_stream_with_standard_format'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:971:in `execute_chunking'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:897:in `emit_buffered'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/event_router.rb:115:in `emit_stream'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/event_router.rb:111:in `emit_array'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:110:in `block in emit'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:109:in `times'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:109:in `emit'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:98:in `run'
  2024-03-27 16:39:44 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
  • emit transaction failed: error_class=IOError error="closed stream"
2024-03-27 16:39:46 +0900 [warn]: #0 emit transaction failed: error_class=IOError error="closed stream" location="/home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:257:in `seek'" tag="test"
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:257:in `seek'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:257:in `write_metadata'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:69:in `commit'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/buffer.rb:377:in `write'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:1069:in `block in handle_stream_with_standard_format'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:977:in `write_guard'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:1068:in `handle_stream_with_standard_format'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:971:in `execute_chunking'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/output.rb:897:in `emit_buffered'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/event_router.rb:115:in `emit_stream'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/event_router.rb:111:in `emit_array'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:110:in `block in emit'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:109:in `times'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:109:in `emit'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin/in_sample.rb:98:in `run'
  2024-03-27 16:39:46 +0900 [warn]: #0 /home/daipom/work/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'

@daipom
Copy link
Contributor

daipom commented Mar 27, 2024

I don't know why only error="closed stream" happens on @larntz's environment.

At least, Buffer on v1.16.4 has race condition issue, and it can cause IOError and emit fail, and it will be fixed by #4447

@daipom
Copy link
Contributor

daipom commented Mar 27, 2024

We have released v1.16.5 to fix this issue.

@daipom
Copy link
Contributor

daipom commented Mar 27, 2024

@larntz Thanks for your report!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
v1.16.5
Development

Successfully merging a pull request may close this issue.

buffer: fix emit error of race condition daipom/fluentd
2 participants
@ashie @daipom