out_file: events except those in the first chunk are not written to files when append is true

[yaojingguo]

Describe the bug

Events except those in the first chunk are not written to files when append is true for out_file plugin.

To Reproduce

1. Run fluentd --setup to generate fluent.conf.
2. Put the following content into fluent.conf.

<match hack.**>
  @type file
  path hack
  append true
  <format>
    @type json
  </format>
  <buffer>
    flush_mode immediate
  </buffer>
</match>

3. Run the following command in a terminal:

$ curl -X POST http://localhost:8888/hack.access  -d 'json={"no":"1"}'
$ cat hack.20211202.log
{"no":"1"}
$ curl -X POST http://localhost:8888/hack.access  -d 'json={"no":"2"}'
$ cat hack.20211202.log
{"no":"1"}

Expected behavior

The content of hack.20211202.log should be:

{"no":"1"}
{"no":"2"}

but was:

{"no":"1"}

Your Environment

• Fluentd version: 1.14.3
• TD Agent version: 1.14.3
• Operating system: macOS 10.15.5
• Kernel version: 19.5.0
• Ruby version: ruby 3.0.2p107 (2021-07-07 revision 0db68f0233) [x86_64-darwin19]

I have used Ruby gem to install Fluentd.

Your Configuration

<match hack.**>
  @type file
  path hack
  append true
  <format>
    @type json
  </format>
  <buffer>
    flush_mode immediate
  </buffer>
</match>

Your Error Log

No error log

Additional context

I have verified that fluentd 1.14.3 which uses ruby 2.7.5p203 (2021-11-24 revision f69aeb8314) [x86_64-linux] does not have this prolem on CentOS Linux release 7.5.1804 (Core). On macOS, I have tried two Ruby 2.x versions. Here is the result:

• ruby 2.6.3p62 (2019-04-16 revision 67580) [universal.x86_64-darwin19] does not have this problem.
• ruby 2.7.5p203 (2021-11-24 revision f69aeb8314) [x86_64-darwin19] has this problem.

[yaojingguo]

The following Fluent::Plugin::Bufffer::Chunk#write_to(io, **kwargs) do the chunk appending:

def write_to(io, **kwargs)
  raise ArgumentError, '`compressed: gzip` can be used for Compressable module' if kwargs[:compressed] == :gzip
  open do |i|
    IO.copy_stream(i, io)
  end
end

The cause of the problem is that IO.copy_stream does not do appending correctly for Ruby 3 and Ruby 2.7.5 when the file specified by io argument is not empty. I have submitted a bug report for this problem to Ruby core: https://bugs.ruby-lang.org/issues/18388 which has been fixed.

If I updates the Fluent::Plugin::FileOutput#write_without_compression(path, chunk), the problem is solved:

def write_without_compression(path, chunk)
  File.open(path, "ab", @file_perm) do |f|
    if @append
      content = chunk.read()
      f.puts content
    else
      chunk.write_to(f)
    end
  end
end

If the above code is the right approach to fix this problem, I am glad to refine the code and add the needed test cases.

[ashie]

I have submitted a bug report for this problem to Ruby core: https://bugs.ruby-lang.org/issues/18388 which has been fixed.

The fix in Ruby: ruby/ruby@b555e65

commit b555e659c4974acc423083b71b1bd5ec6a926046
Author: Nobuyoshi Nakada <[email protected]>
Date:   Sun Dec 5 18:08:55 2021 +0900

    Do not use `fcopyfile` if appending to non-empty file [Bug #18388]
    
    `fcopyfile` appends `src` to `to` and then truncates `to` to it's
    original size.

diff --git a/io.c b/io.c
index b2ca5a69e3..bc64938648 100644
--- a/io.c
+++ b/io.c
@@ -11483,6 +11483,13 @@ nogvl_fcopyfile(struct copy_stream_struct *stp)
         return 0;
     if (lseek(stp->dst_fptr->fd, 0, SEEK_CUR) > (off_t)0) /* if dst IO was already written */
         return 0;
+    if (fcntl(stp->dst_fptr->fd, F_GETFL) & O_APPEND) {
+        /* fcopyfile(3) appends src IO to dst IO and then truncates
+         * dst IO to src IO's original size. */
+        off_t end = lseek(stp->dst_fptr->fd, 0, SEEK_END);
+        lseek(stp->dst_fptr->fd, 0, SEEK_SET);
+        if (end > (off_t)0) return 0;
+    }
 
     if (src_offset > (off_t)0) {
         off_t r;
diff --git a/test/ruby/test_io.rb b/test/ruby/test_io.rb
index 96e572b98d..71a8911fbd 100644
--- a/test/ruby/test_io.rb
+++ b/test/ruby/test_io.rb
@@ -476,6 +476,18 @@ def test_copy_stream_append
     }
   end
 
+  def test_copy_stream_append_to_nonempty
+    with_srccontent("foobar") {|src, content|
+      preface = 'preface'
+      File.write('dst', preface)
+      File.open('dst', 'ab') do |dst|
+        ret = IO.copy_stream(src, dst)
+        assert_equal(content.bytesize, ret)
+        assert_equal(preface + content, File.read("dst"))
+      end
+    }
+  end
+
   def test_copy_stream_smaller
     with_srccontent {|src, content|

[ashie]

Good catch! Thank you for your report, and I'm sorry for our late response.

If the above code is the right approach to fix this problem, I am glad to refine the code and add the needed test cases.

Although I feel it's not proper approach, we may need such workaround against certain Ruby versions.
Could you send a pull request?

[yaojingguo]

#3579 is the workaround.
#3580 is the missed test case which checks events appending without compression for the append option.

@ashie