Buffer - Emit transaction failed: error_class=IOError error="closed stream"

[philipsabri]

Describe the bug

When getting larger event streams of data from the plugin Windows_eventlog2 it eventually crash. When having a limited rate of logs to 200, it is going fine, but we are getting more logs than that incoming so we have to have no limit or much higher. But when having a limit that are full of bytes up to 20x more than the chunk_limit, it crashes.

To Reproduce Have a high stream of data from windows eventlog2 to kafka with a buffer

Expected behavior Split everything up in 1MB chunks and flush them to kafka

Your Environment

fluentd 1.10.2 Windows Server 2019

Your Configuration

<source>
    @type                           windows_eventlog2
    @id                             windows_eventlog2
    read_interval                   2
    tag                             windows.server
    rate_limit                      1000
    channels                        x
    <storage>
        @type                       local
        persistent                  true
        path                        C:\opt\storage\storage20.json
    </storage>
    <parse>
        @type                       winevt_xml
        preserve_qualifiers         true
    </parse>
</source>

<filter>
    @type                           record_transformer
    enable_ruby                     true
    <record>
        time                        ${if record["TimeCreated"] then record["TimeCreated"] end}
    </record>
</filter>

<match windows.server>
    @type                           kafka2
    brokers                         x
    username                        x
    password                        x
    scram_mechanism                 sha512
    ssl_ca_cert                     x
    default_topic                   x

    <format>
        @type                       json
    </format>

    <buffer>
        @type                       file
        path                        C:\opt\buffer\
        flush_mode                  interval
        flush_interval              60s
        retry_type                  periodic
        retry_wait                  5s
        chunk_limit_size            1m
    </buffer>
</match>

I've tried changed the rate_limit and chunk_limit_size

Your Error Log

2020-06-24 11:48:39 +0200 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 2944353bytes
2020-06-24 11:48:43 +0200 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 1357242bytes
2020-06-24 11:48:47 +0200 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 1090726bytes
2020-06-24 11:48:56 +0200 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 1703124bytes
2020-06-24 11:49:04 +0200 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 1103313bytes
2020-06-24 11:49:09 +0200 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 1233125bytes
2020-06-24 11:49:24 +0200 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 5445497bytes
2020-06-24 11:49:38 +0200 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 1623195bytes
2020-06-24 11:49:42 +0200 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 1241962bytes
2020-06-24 11:49:50 +0200 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 1179586bytes
2020-06-24 11:50:03 +0200 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 3004001bytes
2020-06-24 11:50:21 +0200 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 7972611bytes
2020-06-24 11:50:21 +0200 [warn]: #0 emit transaction failed: error_class=IOError error="closed stream" location="C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/plugin/buffer/file_chunk.rb:82:in `pos'" tag="windows.server"
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/plugin/buffer/file_chunk.rb:82:in `pos'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/plugin/buffer/file_chunk.rb:82:in `rollback'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/plugin/buffer.rb:339:in `rescue in block in write'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/plugin/buffer.rb:332:in `block in write'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/plugin/buffer.rb:331:in `each'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/plugin/buffer.rb:331:in `write'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/plugin/output.rb:979:in `block in handle_stream_with_standard_format'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/plugin/output.rb:888:in `write_guard'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/plugin/output.rb:978:in `handle_stream_with_standard_format'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/plugin/output.rb:882:in `execute_chunking'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/plugin/output.rb:808:in `emit_buffered'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/event_router.rb:160:in `emit_events'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/event_router.rb:97:in `emit_stream'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluent-plugin-windows-eventlog-0.5.4/lib/fluent/plugin/in_windows_eventlog2.rb:218:in `on_notify_xml'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluent-plugin-windows-eventlog-0.5.4/lib/fluent/plugin/in_windows_eventlog2.rb:154:in `block in subscribe_channel'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/plugin_helper/timer.rb:80:in `on_timer'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/cool.io-1.6.0/lib/cool.io/loop.rb:88:in `run_once'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/cool.io-1.6.0/lib/cool.io/loop.rb:88:in `run'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/plugin_helper/event_loop.rb:93:in `block in start'
  2020-06-24 11:50:21 +0200 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2020-06-24 11:50:21 +0200 [error]: #0 [windows_eventlog2] Unexpected error raised. Stopping the timer. title=:in_windows_eventlog_allservers_log error_class=IOError error="closed stream"
  2020-06-24 11:50:21 +0200 [error]: #0 suppressed same stacktrace
2020-06-24 11:50:21 +0200 [error]: #0 [windows_eventlog2] Timer detached. title=:in_windows_eventlog_allservers_log

Additional context

When saving all the logs to files of 1MB, its going all fine no crashes.

[repeatedly]

I think supporting in_tail's read_lines_limit feature in windows_eventlog2 is better. With only rate limit, hard to avoid chunk bytes limit exceeds for an emitted event stream warning message with small chunk_limit_size.

2020-06-24 11:50:21 +0200 [warn]: #0 emit transaction failed: error_class=IOError error="closed stream" location="C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.10.2/lib/fluent/plugin/buffer/file_chunk.rb:82:in `pos'" tag="windows.server"

This error should not happen. Will check it.

[cosmo0920]

I think supporting in_tail's read_lines_limit feature in windows_eventlog2 is better.

rate_limit feature seems be same as in_tail's read_lines_limit feature.... There is something what I'm overlooking things...?

https://github.com/fluent-plugins-nursery/winevt_c/pull/9 https://github.com/fluent/fluent-plugin-windows-eventlog/commit/674cd8698349f54b6f68e92ecf96bf886f2142f4

[dshackith]

I see this same issue for logs kubernetes logs forwarded from fluent-bit. Initially the IOError is thrown repeatedly for one chunk that cannot be delivered, and eventually delivery simply stops for all messages. When running multiple threads, some threads keep working, but eventually also show the same error, until all threads are blocked.

[mahmoud-mahdi]

@repeatedly 2023-11-13 05:01:08 +0000 [warn]: emit transaction failed: error_class=IOError error="closed stream" location="/usr/local/share/gems/gems/fluentd-1.14.6/lib/fluent/plugin/buffer/file_chunk.rb:82:in pos'" tag="kubernetes.var.log.pods.identity-providing-zka_auth-11-94n69_0bf0ee60-3756-496b-83e7-7220753ed5c2.auth.0.log" `

We see this warn also in the logs. Did you find anything related to it?

[ashie]

#3089 seems same issue with this. We'll treate it at there.