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
Describe the bug
In version 1.9.3 there was introduced some change which results with the exception:
Here is link to the breaking PR: c5288bc2
Based on my short investigation I can see that the
Tempfileinbinmodefor some reason is closed before it should be.According to Ruby documentation:
There is no issue without binmode (locally modified code). Current solution is to use
1.9.2orcompress text.To Reproduce
Dockerfile:
fluentd.conf:
docker-compose.yaml
Expected behavior
No exception
Your Environment
Your Configuration
Your Error Log
Additional context
N/A