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

IOError error="closed stream" using buffer and gzip compression #3110

Closed
sumo-drosiek opened this issue Aug 20, 2020 · 1 comment · Fixed by #3138
Closed

IOError error="closed stream" using buffer and gzip compression #3110

sumo-drosiek opened this issue Aug 20, 2020 · 1 comment · Fixed by #3138

Comments

@sumo-drosiek
Copy link

Describe the bug

In version 1.9.3 there was introduced some change which results with the exception:

fluentd_1  | 2020-08-20 16:13:03 +0000 [debug]: #0 Created new chunk chunk_id="5ad51651732b92b385132e043b147b60" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=nil, tag="kubernetes.*", variables=nil, seq=0>
fluentd_1  | 2020-08-20 16:13:04 +0000 [debug]: #0 taking back chunk for errors. chunk="5ad51642ca363a0850a5ce90cdc75429"
fluentd_1  | 2020-08-20 16:13:04 +0000 [warn]: #0 failed to flush the buffer. retry_time=0 next_retry_seconds=2020-08-20 16:13:05 +0000 chunk="5ad51642ca363a0850a5ce90cdc75429" error_class=IOError error="closed stream"
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/event.rb:325:in `readpartial'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/event.rb:325:in `each'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/event.rb:325:in `block in each'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/plugin/buffer/chunk.rb:213:in `block in open'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/plugin/buffer/file_chunk.rb:171:in `open'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/plugin/buffer/chunk.rb:205:in `open'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/event.rb:324:in `each'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluent-plugin-sumologic_output-1.7.1/lib/fluent/plugin/out_sumologic.rb:301:in `write'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/plugin/output.rb:1133:in `try_flush'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/plugin/output.rb:1439:in `flush_thread_run'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/plugin/output.rb:461:in `block (2 levels) in start'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'

Here is link to the breaking PR: c5288bc2

Based on my short investigation I can see that the Tempfile in binmode for some reason is closed before it should be.
According to Ruby documentation:

If a block is given, then a Tempfile object will be constructed, and the block is run with said object as argument. The Tempfile object will be automatically closed after the block terminates. The call returns the value of the block.

There is no issue without binmode (locally modified code). Current solution is to use 1.9.2 or compress text.

To Reproduce

Dockerfile:

FROM fluent/fluentd:v1.11.2-debian-1.0

USER root

RUN gem install fluent-plugin-sumologic_output -v 1.7.1
USER fluent

fluentd.conf:

<source>
  @type dummy
  dummy {"log": ""}
  tag kubernetes.*
  rate 20000
</source>
<match kubernetes.**>
  @type sumologic
  endpoint "http://http:3001"
  <buffer>
    @type file
    path /fluentd/buffer
    compress gzip
    flush_interval "5s"
  </buffer>
</match>
<system>
  log_level debug
</system>

docker-compose.yaml

version: '3'
services:
    fluentd:
        build: .
        volumes:
            - ./fluentd.conf:/fluentd/etc/fluent.conf
    http:
        image: jmalloc/echo-server
        environment:
            PORT: 3001

Expected behavior

No exception

Your Environment

  • no need as docker-compose provided

Your Configuration

<source>
  @type dummy
  dummy {"log": ""}
  tag kubernetes.*
  rate 20000
</source>
<match kubernetes.**>
  @type sumologic
  endpoint "http://http:3001"
  <buffer>
    @type file
    path /fluentd/buffer
    compress gzip
    flush_interval "5s"
  </buffer>
</match>
<system>
  log_level debug
</system>

Your Error Log

➜  fluent docker-compose up
Starting fluent_fluentd_1 ... done
Starting fluent_http_1    ... done
Attaching to fluent_fluentd_1, fluent_http_1
http_1     | Echo server listening on port 3001.
fluentd_1  | 2020-08-20 16:13:01 +0000 [info]: parsing config file is succeeded path="/fluentd/etc/fluent.conf"
fluentd_1  | 2020-08-20 16:13:01 +0000 [info]: gem 'fluent-plugin-sumologic_output' version '1.7.1'
fluentd_1  | 2020-08-20 16:13:01 +0000 [info]: gem 'fluentd' version '1.11.2'
fluentd_1  | 2020-08-20 16:13:01 +0000 [debug]: Custom fields: 
fluentd_1  | 2020-08-20 16:13:01 +0000 [debug]: Custom dimensions: 
fluentd_1  | 2020-08-20 16:13:01 +0000 [warn]: both of Plugin @id and path for <storage> are not specified. Using on-memory store.
fluentd_1  | 2020-08-20 16:13:01 +0000 [warn]: both of Plugin @id and path for <storage> are not specified. Using on-memory store.
fluentd_1  | 2020-08-20 16:13:01 +0000 [debug]: No fluent logger for internal event
fluentd_1  | 2020-08-20 16:13:01 +0000 [info]: using configuration file: <ROOT>
fluentd_1  |   <source>
fluentd_1  |     @type dummy
fluentd_1  |     dummy {"log":""}
fluentd_1  |     tag "kubernetes.*"
fluentd_1  |     rate 20000
fluentd_1  |   </source>
fluentd_1  |   <match kubernetes.**>
fluentd_1  |     @type sumologic
fluentd_1  |     endpoint xxxxxx
fluentd_1  |     sumo_client "fluentd-output"
fluentd_1  |     <buffer>
fluentd_1  |       @type "file"
fluentd_1  |       path "/fluentd/buffer"
fluentd_1  |       compress gzip
fluentd_1  |       flush_interval 5s
fluentd_1  |     </buffer>
fluentd_1  |   </match>
fluentd_1  |   <system>
fluentd_1  |     log_level debug
fluentd_1  |   </system>
fluentd_1  | </ROOT>
fluentd_1  | 2020-08-20 16:13:01 +0000 [info]: starting fluentd-1.11.2 pid=6 ruby="2.6.6"
fluentd_1  | 2020-08-20 16:13:01 +0000 [info]: spawn command to main:  cmdline=["/usr/local/bin/ruby", "-Eascii-8bit:ascii-8bit", "/usr/local/bundle/bin/fluentd", "-c", "/fluentd/etc/fluent.conf", "-p", "/fluentd/plugins", "--under-supervisor"]
fluentd_1  | 2020-08-20 16:13:02 +0000 [info]: adding match pattern="kubernetes.**" type="sumologic"
fluentd_1  | 2020-08-20 16:13:02 +0000 [debug]: #0 Custom fields: 
fluentd_1  | 2020-08-20 16:13:02 +0000 [debug]: #0 Custom dimensions: 
fluentd_1  | 2020-08-20 16:13:02 +0000 [info]: adding source type="dummy"
fluentd_1  | 2020-08-20 16:13:02 +0000 [warn]: #0 both of Plugin @id and path for <storage> are not specified. Using on-memory store.
fluentd_1  | 2020-08-20 16:13:02 +0000 [warn]: #0 both of Plugin @id and path for <storage> are not specified. Using on-memory store.
fluentd_1  | 2020-08-20 16:13:02 +0000 [debug]: #0 No fluent logger for internal event
fluentd_1  | 2020-08-20 16:13:02 +0000 [info]: #0 starting fluentd worker pid=16 ppid=6 worker=0
fluentd_1  | 2020-08-20 16:13:02 +0000 [debug]: #0 restoring buffer file: path = /fluentd/buffer/buffer.b5ad5164796799b10ea4b5ecff7d98538.log
fluentd_1  | 2020-08-20 16:13:02 +0000 [debug]: #0 restoring buffer file: path = /fluentd/buffer/buffer.q5ad51642ca363a0850a5ce90cdc75429.log
fluentd_1  | 2020-08-20 16:13:02 +0000 [debug]: #0 buffer started instance=69845180126480 stage_size=651046 queue_size=941127
fluentd_1  | 2020-08-20 16:13:02 +0000 [info]: #0 fluentd worker is now running worker=0
fluentd_1  | 2020-08-20 16:13:02 +0000 [debug]: #0 flush_thread actually running
fluentd_1  | 2020-08-20 16:13:02 +0000 [debug]: #0 enqueue_thread actually running
fluentd_1  | 2020-08-20 16:13:03 +0000 [debug]: #0 Created new chunk chunk_id="5ad51651732b92b385132e043b147b60" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=nil, tag="kubernetes.*", variables=nil, seq=0>
fluentd_1  | 2020-08-20 16:13:04 +0000 [debug]: #0 taking back chunk for errors. chunk="5ad51642ca363a0850a5ce90cdc75429"
fluentd_1  | 2020-08-20 16:13:04 +0000 [warn]: #0 failed to flush the buffer. retry_time=0 next_retry_seconds=2020-08-20 16:13:05 +0000 chunk="5ad51642ca363a0850a5ce90cdc75429" error_class=IOError error="closed stream"
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/event.rb:325:in `readpartial'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/event.rb:325:in `each'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/event.rb:325:in `block in each'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/plugin/buffer/chunk.rb:213:in `block in open'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/plugin/buffer/file_chunk.rb:171:in `open'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/plugin/buffer/chunk.rb:205:in `open'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/event.rb:324:in `each'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluent-plugin-sumologic_output-1.7.1/lib/fluent/plugin/out_sumologic.rb:301:in `write'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/plugin/output.rb:1133:in `try_flush'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/plugin/output.rb:1439:in `flush_thread_run'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/plugin/output.rb:461:in `block (2 levels) in start'
fluentd_1  |   2020-08-20 16:13:04 +0000 [warn]: #0 /usr/local/bundle/gems/fluentd-1.11.2/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
http_1     | 172.26.0.3:53046 | POST /
fluentd_1  | 2020-08-20 16:13:07 +0000 [warn]: #0 retry succeeded. chunk_id="5ad51642ca363a0850a5ce90cdc75429"
fluentd_1  | 2020-08-20 16:13:08 +0000 [debug]: #0 Created new chunk chunk_id="5ad51656380282515fe2351bf5df6621" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=nil, tag="kubernetes.*", variables=nil, seq=0>
fluentd_1  | 2020-08-20 16:13:09 +0000 [debug]: #0 taking back chunk for errors. chunk="5ad5164796799b10ea4b5ecff7d98538"
fluentd_1  | 2020-08-20 16:13:09 +0000 [warn]: #0 failed to flush the buffer. retry_time=0 next_retry_seconds=2020-08-20 16:13:10 +0000 chunk="5ad5164796799b10ea4b5ecff7d98538" error_class=IOError error="closed stream"
fluentd_1  |   2020-08-20 16:13:09 +0000 [warn]: #0 suppressed same stacktrace

Additional context
N/A
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

chunk: fix binmode usage for prevent gc mocyuto/fluentd
2 participants
@frankreno @sumo-drosiek