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.

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

Fluentd always "Created new chunk" for every single event with armv7l environment #3088

Closed
mittyorz opened this issue Jul 28, 2020 · 9 comments · Fixed by #3092
Closed

Fluentd always "Created new chunk" for every single event with armv7l environment #3088

mittyorz opened this issue Jul 28, 2020 · 9 comments · Fixed by #3092
Assignees
Labels
bug Something isn't working

Comments

@mittyorz
Copy link

mittyorz commented Jul 28, 2020

Describe the bug

I'm trying to use fluentd on Raspberry Pi 3B+ with Arch Linux ARM (armv7l).
With armv7l environment, fluentd always creates new chunk for every single event.

This issue does not happen in aarch64 environment.

To Reproduce

Install fluentd to armv7l environment, and send some event messages.
Fluentd creates many small chunk files, just 1 log line each.

Expected behavior

Fluentd should not create a small chunk file for an each single event.

Your Environment

Your Configuration

<source>
  @type forward
  port 24224
</source>

<match test.**>
  @type file
  path log/%Y%m%d.${tag}
  append true
  <buffer tag,time>
    @type file
    path log/
    timekey 1d
  </buffer>
</match>

Your Error Log

$ for i in {1..100}; do echo '{"status":"OK"}' | fluent-cat test; done produces following outputs.

  • mitty@raspi-202:~/works/fluentd$ fluentd -c fluent.conf -v
2020-07-28 23:23:21 +0900 [info]: fluent/log.rb:327:info: parsing config file is succeeded path="fluent.conf"
2020-07-28 23:23:21 +0900 [info]: fluent/log.rb:327:info: gem 'fluentd' version '1.11.1'
2020-07-28 23:23:21 +0900 [debug]: fluent/log.rb:306:debug: No fluent logger for internal event
2020-07-28 23:23:21 +0900 [info]: fluent/log.rb:327:info: using configuration file: <ROOT>
  <source>
    @type forward
    port 24224
  </source>
  <match test.**>
    @type file
    path "log/%Y%m%d.${tag}"
    append true
    <buffer tag,time>
      @type "file"
      path "log/"
      timekey 1d
    </buffer>
  </match>
</ROOT>
2020-07-28 23:23:21 +0900 [info]: fluent/log.rb:327:info: starting fluentd-1.11.1 pid=5102 ruby="2.7.1"
2020-07-28 23:23:21 +0900 [info]: fluent/log.rb:327:info: spawn command to main:  cmdline=["/usr/bin/ruby", "-Eascii-8bit:ascii-8bit", "/home/mitty/.gem/ruby/2.7.0/bin/fluentd", "-c", "fluent.conf", "-v", "--under-supervisor"]
2020-07-28 23:23:25 +0900 [info]: fluent/log.rb:327:info: adding match pattern="test.**" type="file"
2020-07-28 23:23:25 +0900 [info]: fluent/log.rb:327:info: adding source type="forward"
2020-07-28 23:23:25 +0900 [debug]: #0 fluent/log.rb:306:debug: No fluent logger for internal event
2020-07-28 23:23:25 +0900 [info]: #0 fluent/log.rb:327:info: starting fluentd worker pid=5108 ppid=5102 worker=0
2020-07-28 23:23:25 +0900 [debug]: #0 fluent/log.rb:306:debug: buffer started instance=1020 stage_size=0 queue_size=0
2020-07-28 23:23:25 +0900 [debug]: #0 fluent/log.rb:306:debug: flush_thread actually running
2020-07-28 23:23:25 +0900 [debug]: #0 fluent/log.rb:306:debug: enqueue_thread actually running
2020-07-28 23:23:25 +0900 [info]: #0 fluent/log.rb:327:info: listening port port=24224 bind="0.0.0.0"
2020-07-28 23:23:25 +0900 [info]: #0 fluent/log.rb:327:info: fluentd worker is now running worker=0
2020-07-28 23:24:06 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813114211104836af4bdf533141ce" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:08 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8131329ac65c26419587e9f3f888e" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:10 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8131510e3d1c5015ad11ef291fbcf" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:12 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81316f67c6e1746aba6a59e065aeb" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:14 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81318dceeccbfdf1a81b15658d98a" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:16 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8131ac5a610e50c59e49c9adb86d6" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:18 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8131cad2ae212e99211c1acd2cc5e" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:20 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8131e9712aa71651da6a389b41e3d" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:22 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81320829f5be81c395d315ca54d44" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:24 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813226ab837b2e6649f7a028fc4f3" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:26 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81324565df9406ca2a9a1923568a6" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:28 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813263dd9dc05f4b121589505ae41" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:30 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8132825310d945fdfe3a9be9dae66" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:32 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8132a0c8e49c9cc1e5f2ea92b36f2" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:34 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8132bf7906c99c27d8aa55c630842" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:36 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8132de1d43a81ee55cc8e4e74899e" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:38 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8132fc9c75b8689fb80fb31b328d8" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:40 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81331b06c7420edb1874a0d6ed39a" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:42 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813339de16e503b51c41bfdf9fc8a" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:44 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8133588f9362a3bcccf6b611a274c" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:46 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8133774502621e3ac15826ecf5086" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:48 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813395ea19a45ba3bd17f3b03b4e4" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:50 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8133b46934008145deb1c5fd1bc4b" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:52 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8133d2edc841e98f85c538c70ec96" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:54 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8133f15f9b0e2d023bdda0377156f" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:56 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81340fcd90270da89b090f6f78a6d" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:24:58 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81342e6bbc98e504a69db2e6ccca3" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:00 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81344ce5e1daab61228a53eb415c3" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:02 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81346b8c75700ba571a9cbfe27e33" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:04 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813489fbb70b7497e4d3635a4415a" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:06 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8134a89a04f2ace6d9b5cfd1332f4" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:08 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8134c72afd799524c1fb3e4f669cd" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:10 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8134e5b41edaa60e45625ec27f9fa" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:12 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8135045bdf22755f0adc8088efadf" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:14 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813522c73d40f498919e046dd067e" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:16 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813541426028f1f73b3939a482052" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:18 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81355faddb6c1160ccd0282b7b663" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:20 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81357e262281d0cbe3186b7e50e3d" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:22 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81359cdc4c5fb8cd4872d0e0cbd2c" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:24 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8135bb798d5150b439cee2ee10a6b" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:26 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8135d9f1ba9b5f9ef8a73d56daa68" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:28 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8135f892c2c070ab1820516f463ff" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:30 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8136188241b2e966f13f60e88fd84" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:32 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81363a6278b36499d18dec70ba2c4" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:34 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81365bd3833e7660c8723b5a436b9" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:36 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81367dd66ef4488c2fab593ebca33" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:38 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81369c73063829dd86cb2b23eb439" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:40 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8136baf8c3d0db74f7274ac287531" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:42 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8136d973bbd6bf504d0e8f92ab0c5" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:44 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8136f7e4389c65a61ec48d7220f85" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:46 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8137165a163160ce45fabd0c2f19c" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:48 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8137351348178c7e7a48b483f744f" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:50 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813753aaf801b041c96e9491d0bb3" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:52 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81377257c8c7c57738d02aeefb1e2" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:54 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813790d025a66d68a0e6ba92d2da9" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:56 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8137af7be76b08a9076370911a1e5" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:25:58 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8137cdfaa75491d70b6b38af3782c" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:00 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8137eca2718db2afb2d8e824b42bb" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:02 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81380b09aef2704b8504900566dab" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:04 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813829e92362576919488839bdd68" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:06 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8138488d4cd072911f77ce7c58a0e" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:08 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81386712796e64875bc68db1abbfd" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:10 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8138858259f6a9132288f7b7df3b7" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:12 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8138a41d12f8af8c589f18f759405" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:14 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8138c2a226366769485dab1d567fb" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:16 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8138e115aee2c9a2012dbe729b147" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:18 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8138ff6f63e3e093f9c6c3a64c5a5" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:20 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81391dface99eda1b30f398b8e8c1" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:22 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81393c9103a05e41dbbc6f999025d" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:24 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab81395b064a52d3808e9267dace043" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:26 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813979904fa023c82e03d8cc0b2b9" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:28 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813997f4cb59e9107d82b8377e8cc" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:30 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8139b675c69f96a71d0831868a835" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:32 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8139d5196401a2a2d5f8a54ac076e" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:34 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab8139f37fbc242fa3abb98e6576c22" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:36 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813a11fe4c2e2333846c0ed09a1ad" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:38 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813a3083dd42b04922e4dabd21be5" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:40 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813a4f382e2e620603d2c46e63ac8" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:42 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813a6dd8a7c383aa782ed91812dfc" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:44 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813a8c462796276522edd8bafeb5b" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:46 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813aaab4a6c53e30ce6533817ea29" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:48 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813ac92028f787da8217413ed898f" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:50 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813ae7c8477e609e97bba0bee06b5" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:52 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813b065895694dc118f17e3c0658c" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:54 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813b24ee070a81a455cc9d59a2e34" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:56 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813b43615be5356dad6a3abe8400c" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:26:58 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813b61db899cfcfde1cf87a92de41" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:27:00 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813b80489a13b5f64eefe692735e8" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:27:02 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813b9ec4bee1f2cd79643cb3630fb" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:27:04 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813bbd6b3ede0914c83b9a342cd2a" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:27:06 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813bdbf5116cc356081abe6ca3f33" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:27:08 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813bfa8d276e2ddded2b35da39663" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:27:10 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813c190e8a5fc302e25e884a31f2f" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:27:12 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813c37765cde4ca96b7f9799723b6" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:27:14 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813c55dec23b4be801f797c81f354" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:27:16 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813c745d23e0b8c4ed299502a6c09" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:27:18 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813c92cf1cf78d6fd6a6bd2d78696" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:27:20 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813cb16caf2b824b0ee51ad5723af" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:27:22 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813ccfe009de6d5356ebc236ce53c" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
2020-07-28 23:27:24 +0900 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5ab813cee832f2cc700a927fcdf7fa90" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1595862000, tag="test", variables=nil, seq=0>
  • mitty@raspi-202:~/works/fluentd$ ls log/ | head
buffer.b5ab813114211104836af4bdf533141ce.log
buffer.b5ab813114211104836af4bdf533141ce.log.meta
buffer.b5ab8131329ac65c26419587e9f3f888e.log
buffer.b5ab8131329ac65c26419587e9f3f888e.log.meta
buffer.b5ab8131510e3d1c5015ad11ef291fbcf.log
buffer.b5ab8131510e3d1c5015ad11ef291fbcf.log.meta
buffer.b5ab81316f67c6e1746aba6a59e065aeb.log
buffer.b5ab81316f67c6e1746aba6a59e065aeb.log.meta
buffer.b5ab81318dceeccbfdf1a81b15658d98a.log
buffer.b5ab81318dceeccbfdf1a81b15658d98a.log.meta
  • mitty@raspi-202:~/works/fluentd$ ls log/ | wc -l
200
  • mitty@raspi-202:~/works/fluentd$ wc -l log/*.log | head
   1 log/buffer.b5ab813114211104836af4bdf533141ce.log
   1 log/buffer.b5ab8131329ac65c26419587e9f3f888e.log
   1 log/buffer.b5ab8131510e3d1c5015ad11ef291fbcf.log
   1 log/buffer.b5ab81316f67c6e1746aba6a59e065aeb.log
   1 log/buffer.b5ab81318dceeccbfdf1a81b15658d98a.log
   1 log/buffer.b5ab8131ac5a610e50c59e49c9adb86d6.log
   1 log/buffer.b5ab8131cad2ae212e99211c1acd2cc5e.log
   1 log/buffer.b5ab8131e9712aa71651da6a389b41e3d.log
   1 log/buffer.b5ab81320829f5be81c395d315ca54d44.log
   1 log/buffer.b5ab813226ab837b2e6649f7a028fc4f3.log

Additional context

I found similar issue #2713 and commented out hash method like following:

--- .gem/ruby/2.7.0/gems/fluentd-1.11.1/lib/fluent/plugin/buffer.rb.orig        2020-07-28 22:44:42.518220280 +0900
+++ .gem/ruby/2.7.0/gems/fluentd-1.11.1/lib/fluent/plugin/buffer.rb     2020-07-28 23:14:42.816185713 +0900
@@ -151,9 +151,9 @@
         # But, this optimization has a side effect on Windows due to differing object_id.
         # This difference causes flood of buffer files.
         # So, this optimization should be enabled on non-Windows platform.
-        def hash
-          timekey.object_id
-        end unless Fluent.windows?
+        # def hash
+        #   timekey.object_id
+        # end unless Fluent.windows?
       end

       # for tests

And the problem was gone. (only one chunk file was created as expected)

I also tested fluentd in the aarch64 environments (AWS EC2 m6g.medium instance and qemu-arm emulation with version 5.0.0) and the problem did not happen.

hash method was introduced at v1.7.0 so I tested fluentd version 1.6.0 and that is not also affected.

@repeatedly
Copy link
Member

I don't have armv7l environment for now.
Do you have any recommended service for testing armv7l or could you send a patch to disable def hash on armv7l?

@repeatedly repeatedly added the bug Something isn't working label Jul 29, 2020
@mittyorz
Copy link
Author

I tested this problem with Arm chroot environment using qemu+binfmt and I could reproduced it.
I'm using Arch Linux for daily use, so I referred to the following page.
https://nerdstuff.org/posts/2020/2020-003_simplest_way_to_create_an_arm_chroot/
(I didn't test this with any other distributions.)

I can't find any online services easy to use that provide the armv7l environment.

@ashie
Copy link
Member

ashie commented Jul 30, 2020

--- .gem/ruby/2.7.0/gems/fluentd-1.11.1/lib/fluent/plugin/buffer.rb.orig        2020-07-28 22:44:42.518220280 +0900
+++ .gem/ruby/2.7.0/gems/fluentd-1.11.1/lib/fluent/plugin/buffer.rb     2020-07-28 23:14:42.816185713 +0900
@@ -151,9 +151,9 @@
         # But, this optimization has a side effect on Windows due to differing object_id.
         # This difference causes flood of buffer files.
         # So, this optimization should be enabled on non-Windows platform.
-        def hash
-          timekey.object_id
-        end unless Fluent.windows?
+        # def hash
+        #   timekey.object_id
+        # end unless Fluent.windows?
       end

       # for tests

Using object_id seems unsuitable for it because:

On Windows:
irb(main):140:0> RUBY_VERSION
=> "2.7.1"
irb(main):141:0> a = 2**30 - 1
irb(main):142:0> a.object_id
=> 2147483647
irb(main):143:0> a = 2**30 - 1
irb(main):144:0> a.object_id
=> 2147483647
irb(main):145:0> a = 2**30
irb(main):146:0> a.object_id
=> 640
irb(main):147:0> a = 2**30
irb(main):148:0> a.object_id
=> 660


On GNU/Linux x86_64:
irb(main):001:0> RUBY_VERSION
=> "2.7.0"
irb(main):002:0> a = 2**30 - 1
irb(main):003:0> a.object_id
=> 2147483647
irb(main):004:0> a = 2**30 - 1
irb(main):005:0> a.object_id
=> 2147483647
irb(main):006:0> a = 2**30
irb(main):007:0> a.object_id
=> 2147483649
irb(main):008:0> a = 2**30
irb(main):009:0> a.object_id
=> 2147483649
irb(main):010:0> a = 2**62 - 1
irb(main):011:0> a.object_id
=> 9223372036854775807
irb(main):012:0> a = 2**62 - 1
irb(main):013:0> a.object_id
=> 9223372036854775807
irb(main):014:0> a = 2**62
irb(main):015:0> a.object_id
=> 180
irb(main):016:0> a = 2**62
irb(main):017:0> a.object_id
=> 200

@mittyorz
Copy link
Author

I built Raspberry Pi OS armv7l qemu chroot environment like following steps, and it was also reproducible.

build Raspberry Pi OS armv7l on Ubuntu 18.04 x86_64 with AWS EC2

  • ubuntu/images/hvm-ssd/ubuntu-bionic-18.04-amd64-server-20200708.1 - ami-00b90aa0c4c5188a4
  • t3a.small

binfmt-support qemu-user-static

  • ubuntu@ip-172-31-23-7:~$ sudo apt install binfmt-support qemu-user-static
  • ubuntu@ip-172-31-23-7:~$ ls /proc/sys/fs/binfmt_misc
python3.6     qemu-cris        qemu-mips64el    qemu-ppc64le  qemu-sparc32plus
qemu-aarch64  qemu-m68k        qemu-mipsel      qemu-s390x    qemu-sparc64
qemu-alpha    qemu-microblaze  qemu-ppc         qemu-sh4      register
qemu-arm      qemu-mips        qemu-ppc64       qemu-sh4eb    status
qemu-armeb    qemu-mips64      qemu-ppc64abi32  qemu-sparc

mount Raspberry Pi OS

total 2252548
-rw-r--r-- 1 ubuntu ubuntu 1853882368 May 27 07:24 2020-05-27-raspios-buster-lite-armhf.img
-rw-rw-r-- 1 ubuntu ubuntu  452715448 May 28 02:01 raspios_lite_armhf_latest
  • ubuntu@ip-172-31-23-7:~/works/arm$ sudo losetup -fP 2020-05-27-raspios-buster-lite-armhf.img
  • ubuntu@ip-172-31-23-7:~/works/arm$ sudo fdisk -l /dev/loop2
Disk /dev/loop2: 1.7 GiB, 1853882368 bytes, 3620864 sectors
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disklabel type: dos
Disk identifier: 0x2fed7fee

Device       Boot  Start     End Sectors  Size Id Type
/dev/loop2p1        8192  532479  524288  256M  c W95 FAT32 (LBA)
/dev/loop2p2      532480 3620863 3088384  1.5G 83 Linux
  • ubuntu@ip-172-31-23-7:~/works/arm$ mkdir root
  • ubuntu@ip-172-31-23-7:~/works/arm$ sudo mount /dev/loop2p2 root/

chroot to Raspberry Pi OS

  • ubuntu@ip-172-31-23-7:~/works/arm$ sudo rm root/etc/ld.so.preload
    • to avoid "ERROR: ld.so: object '/usr/lib/arm-linux-gnueabihf/libarmmem-${PLATFORM}.so' from /etc/ld.so.preload cannot be preloaded (cannot open shared object file): ignored." messages
  • ubuntu@ip-172-31-23-7:~/works/arm$ sudo cp -a /usr/bin/qemu-arm-static root/usr/bin/
  • ubuntu@ip-172-31-23-7:~/works/arm$ sudo chroot root/ /bin/bash

  • root@ip-172-31-23-7:/# uname -a
Linux ip-172-31-23-7 5.3.0-1030-aws #32~18.04.1-Ubuntu SMP Tue Jun 30 23:04:16 UTC 2020 armv7l GNU/Linux

test with Raspberry Pi OS armv7l

  • root@ip-172-31-23-7:/# apt update
  • root@ip-172-31-23-7:/# apt install ruby ruby-dev build-essential
  • root@ip-172-31-23-7:/# sudo gem install fluentd
  • root@ip-172-31-23-7:/# mkdir -p /root/works/fluentd/log
  • root@ip-172-31-23-7:/# cd root/works/fluentd/
  • root@ip-172-31-23-7:/root/works/fluentd# cat > fluent.conf
<source>
  @type forward
  port 24224
</source>

<match test.**>
  @type file
  path log/%Y%m%d.${tag}
  append true
  <buffer tag,time>
    @type file
    path log/
    timekey 1d
  </buffer>
</match>

  • root@ip-172-31-23-7:/root/works/fluentd# fluentd -c fluent.conf -v
2020-07-30 15:20:29 +0100 [info]: fluent/log.rb:327:info: parsing config file is succeeded path="fluent.conf"
2020-07-30 15:20:29 +0100 [info]: fluent/log.rb:327:info: gem 'fluentd' version '1.11.1'
2020-07-30 15:20:29 +0100 [debug]: fluent/log.rb:306:debug: No fluent logger for internal event
2020-07-30 15:20:29 +0100 [info]: fluent/log.rb:327:info: using configuration file: <ROOT>
  <source>
    @type forward
    port 24224
  </source>
  <match test.**>
    @type file
    path "log/%Y%m%d.${tag}"
    append true
    <buffer tag,time>
      @type "file"
      path "log/"
      timekey 1d
    </buffer>
  </match>
</ROOT>
2020-07-30 15:20:29 +0100 [info]: fluent/log.rb:327:info: starting fluentd-1.11.1 pid=14806 ruby="2.5.5"
2020-07-30 15:20:29 +0100 [info]: fluent/log.rb:327:info: spawn command to main:  cmdline=["/usr/bin/ruby2.5", "-Eascii-8bit:ascii-8bit", "/usr/local/bin/fluentd", "-c", "fluent.conf", "-v", "--under-supervisor"]
2020-07-30 15:20:33 +0100 [info]: fluent/log.rb:327:info: adding match pattern="test.**" type="file"
2020-07-30 15:20:34 +0100 [info]: fluent/log.rb:327:info: adding source type="forward"
2020-07-30 15:20:34 +0100 [debug]: #0 fluent/log.rb:306:debug: No fluent logger for internal event
2020-07-30 15:20:34 +0100 [info]: #0 fluent/log.rb:327:info: starting fluentd worker pid=14820 ppid=14806 worker=0
2020-07-30 15:20:34 +0100 [debug]: #0 fluent/log.rb:306:debug: buffer started instance=7285776 stage_size=0 queue_size=0
2020-07-30 15:20:34 +0100 [info]: #0 fluent/log.rb:327:info: listening port port=24224 bind="0.0.0.0"
2020-07-30 15:20:34 +0100 [debug]: #0 fluent/log.rb:306:debug: flush_thread actually running
2020-07-30 15:20:34 +0100 [debug]: #0 fluent/log.rb:306:debug: enqueue_thread actually running
Unsupported setsockopt level=1 optname=13
2020-07-30 15:20:34 +0100 [warn]: #0 fluent/log.rb:348:warn: failed to set socket option sock=TCPServer option=:SO_LINGER value="\x01\x00\x00\x00\x00\x00\x00\x00" error_class=Errno::ENOPROTOOPT error="Protocol not available - setsockopt(2)"
2020-07-30 15:20:34 +0100 [info]: #0 fluent/log.rb:327:info: fluentd worker is now running worker=0
  • root@ip-172-31-23-7:/# for i in {1..100}; do echo '{"status":"OK"}' | fluent-cat test; done
Unsupported setsockopt level=1 optname=13
2020-07-30 15:21:16 +0100 [warn]: #0 fluent/log.rb:348:warn: failed to set socket option sock=TCPSocket option=:SO_LINGER value="\x01\x00\x00\x00\x00\x00\x00\x00" error_class=Errno::ENOPROTOOPT error="Protocol not available - setsockopt(2)"
2020-07-30 15:21:16 +0100 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5aba962a8dbd78235b1913f6abf6ced2" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1596063600, tag="test", variables=nil, seq=0>
Unsupported setsockopt level=1 optname=13
2020-07-30 15:21:19 +0100 [warn]: #0 fluent/log.rb:348:warn: failed to set socket option sock=TCPSocket option=:SO_LINGER value="\x01\x00\x00\x00\x00\x00\x00\x00" error_class=Errno::ENOPROTOOPT error="Protocol not available - setsockopt(2)"
2020-07-30 15:21:19 +0100 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5aba962ce5f1cbbff3c6d97d8bcdd511" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1596063600, tag="test", variables=nil, seq=0>
Unsupported setsockopt level=1 optname=13
2020-07-30 15:21:21 +0100 [warn]: #0 fluent/log.rb:348:warn: failed to set socket option sock=TCPSocket option=:SO_LINGER value="\x01\x00\x00\x00\x00\x00\x00\x00" error_class=Errno::ENOPROTOOPT error="Protocol not available - setsockopt(2)"
2020-07-30 15:21:21 +0100 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5aba962f3e6f032173ec02e7afb0b541" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1596063600, tag="test", variables=nil, seq=0>
Unsupported setsockopt level=1 optname=13
2020-07-30 15:21:23 +0100 [warn]: #0 fluent/log.rb:348:warn: failed to set socket option sock=TCPSocket option=:SO_LINGER value="\x01\x00\x00\x00\x00\x00\x00\x00" error_class=Errno::ENOPROTOOPT error="Protocol not available - setsockopt(2)"
2020-07-30 15:21:23 +0100 [debug]: #0 fluent/log.rb:306:debug: Created new chunk chunk_id="5aba9631923a4b77523794cd48865ae6" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1596063600, tag="test", variables=nil, seq=0>

(snip)
  • root@ip-172-31-23-7:/# ls /root/works/fluentd/log/ | wc -l
200

@cosmo0920
Copy link
Contributor

I'm confirming this issue on Jetson TX2 and its docker runtime.

@cosmo0920
Copy link
Contributor

cosmo0920 commented Jul 31, 2020

test with Ubuntu 18.04 on Jetson TX2

Pull armhf image

$ sudo docker run -p 24224:24224 -it --rm fluent/fluentd:v1.11.1-debian-armhf-1.0 bash
[sudo] password for hhatake:
Unable to find image 'fluent/fluentd:v1.11.1-debian-armhf-1.0' locally
v1.11.1-debian-armhf-1.0: Pulling from fluent/fluentd
cff0731da2e4: Pull complete
3bbeb0ded58d: Pull complete
d6159fbed770: Pull complete
7ba732bafeb6: Pull complete
26d84f63917d: Pull complete
cc3dbfa79d33: Pull complete
d00e10516f07: Pull complete
d2a85aeebace: Pull complete
d616fe576d6f: Pull complete
f6229733e01f: Pull complete
d207c17a5239: Pull complete
151e4c2b3c9e: Pull complete
eab6f534dc30: Pull complete
Digest: sha256:b6891b974f8ac91f0ca5d4940ec6299ef72c2213a66ed032967ac36c16dd0970
Status: Downloaded newer image for fluent/fluentd:v1.11.1-debian-armhf-1.0

Create configuration file

$ echo '<source>
  @type forward
  port 24224
</source>

<match test.**>
  @type file
  path log/%Y%m%d.${tag}
  append true
  <buffer tag,time>
    @type file
    path log/
    timekey 1d
  </buffer>
</match>
' > /fluentd/etc/issue3088.conf

Run Fluentd

fluent@b1016b2906f2:/$ cd fluentd
fluent@b1016b2906f2:/fluentd$ fluentd -c /fluentd/etc/issue3088.conf
2020-07-31 06:58:39 +0000 [info]: parsing config file is succeeded path="/fluentd/etc/issue3088.conf"
2020-07-31 06:58:39 +0000 [info]: gem 'fluentd' version '1.11.1'
2020-07-31 06:58:39 +0000 [info]: using configuration file: <ROOT>
  <source>
    @type forward
    port 24224
  </source>
  <match test.**>
    @type file
    path "log/%Y%m%d.${tag}"
    append true
    <buffer tag,time>
      @type "file"
      path "log/"
      timekey 1d
    </buffer>
  </match>
</ROOT>
2020-07-31 06:58:39 +0000 [info]: starting fluentd-1.11.1 pid=43 ruby="2.6.6"
2020-07-31 06:58:39 +0000 [info]: spawn command to main:  cmdline=["/usr/local/bin/ruby", "-Eascii-8bit:ascii-8bit", "/usr/local/bundle/bin/fluentd", "-c", "/fluentd/etc/issue3088.conf", "--under-supervisor"]
2020-07-31 06:58:41 +0000 [info]: adding match pattern="test.**" type="file"
2020-07-31 06:58:41 +0000 [info]: adding source type="forward"
2020-07-31 06:58:41 +0000 [info]: #0 starting fluentd worker pid=49 ppid=43 worker=0
2020-07-31 06:58:41 +0000 [info]: #0 listening port port=24224 bind="0.0.0.0"
2020-07-31 06:58:41 +0000 [info]: #0 fluentd worker is now running worker=0

Result

From outside armhf container:

$ for i in {1..100}; do echo '{"status":"OK"}' | bundle exec fluent-cat test; done

Inside running Fluentd container:

fluent@b1016b2906f2:/fluentd$ ls log | wc -l
200

I could reproduce this issue with armhf container.

@cosmo0920
Copy link
Contributor

cosmo0920 commented Jul 31, 2020

Using fluent/fluentd:v1.11.1-debian-arm64-1.0 image does not create flood of buffer files:

$ sudo docker run -p 24224:24224 -it --rm fluent/fluentd:v1.11.1-debian-arm64-1.0 bash

<same with the above steps>

fluent@a982d50927e4:/fluentd$ ls log | wc -l
2

@cosmo0920
Copy link
Contributor

cosmo0920 commented Jul 31, 2020

The root cause of this issue is:

timekey should be bigger than 2**30-1:

irb(main):005:0> Time.parse('2016-04-11 16:40:00 +0000').to_i > 2**30-1
=> true

But, Ruby on Windows and 32bit Linux environment does not handle such big integer's object_id as stable ids:
#3088 (comment)

That is why this issue is caused.

cosmo0920 added a commit that referenced this issue Jul 31, 2020
Object#object_id should return values the following rule:

```
On Windows:
irb(main):140:0> RUBY_VERSION
=> "2.7.1"
irb(main):141:0> a = 2**30 - 1
irb(main):142:0> a.object_id
=> 2147483647
irb(main):143:0> a = 2**30 - 1
irb(main):144:0> a.object_id
=> 2147483647
irb(main):145:0> a = 2**30
irb(main):146:0> a.object_id
=> 640
irb(main):147:0> a = 2**30
irb(main):148:0> a.object_id
=> 660
```

For Windows, less than equal `2^30 - 1` should be stable and be able to use with #hash.

---

```
On GNU/Linux x86_64:
irb(main):001:0> RUBY_VERSION
=> "2.7.0"
irb(main):002:0> a = 2**30 - 1
irb(main):003:0> a.object_id
=> 2147483647
irb(main):004:0> a = 2**30 - 1
irb(main):005:0> a.object_id
=> 2147483647
irb(main):006:0> a = 2**30
irb(main):007:0> a.object_id
=> 2147483649
irb(main):008:0> a = 2**30
irb(main):009:0> a.object_id
=> 2147483649
irb(main):010:0> a = 2**62 - 1
irb(main):011:0> a.object_id
=> 9223372036854775807
irb(main):012:0> a = 2**62 - 1
irb(main):013:0> a.object_id
=> 9223372036854775807
irb(main):014:0> a = 2**62
irb(main):015:0> a.object_id
=> 180
irb(main):016:0> a = 2**62
irb(main):017:0> a.object_id
=> 200
```

For GNU/Linux x86_64, less than equal `2^62 - 1` should be stable and be able to use with #hash.

---

```
On GNU/Linux aarch64:
irb(main):001:0> RUBY_VERSION
=> "2.7.1"
irb(main):002:0> a = 2**30 - 1
irb(main):003:0> a.object_id
=> 2147483647
irb(main):004:0> a = 2**30 - 1
irb(main):005:0> a.object_id
=> 2147483647
irb(main):006:0> a = 2**30
irb(main):007:0> a.object_id
=> 2147483649
irb(main):008:0> a = 2**30
irb(main):009:0> a.object_id
=> 2147483649
irb(main):010:0> a = 2**62 -1
irb(main):011:0> a.object_id
=> 9223372036854775807
irb(main):012:0> a = 2**62 -1
irb(main):013:0> a.object_id
=> 9223372036854775807
irb(main):014:0> a = 2**62
irb(main):015:0> a.object_id
=> 180
irb(main):016:0> a = 2**62
irb(main):017:0> a.object_id
=> 200
```
For GNU/Linux aarch64, less than equal `2^62 - 1` should be stable and be able to use with #hash.

---

```
On GNU/Linux armv7l
irb(main):001:0> RUBY_VERSION
=> "2.6.6"
irb(main):002:0> a = 2**30 -1
=> 1073741823
irb(main):003:0> a.object_id
=> 2147483647
irb(main):004:0> a = 2**30 -1
=> 1073741823
irb(main):005:0> a.object_id
=> 2147483647
irb(main):006:0> a = 2**30
=> 1073741824
irb(main):007:0> a.object_id
=> -209995496
irb(main):008:0> a = 2**30
=> 1073741824
irb(main):009:0> a.object_id
=> -210001856
irb(main):010:0> a = 2**62 -1
=> 4611686018427387903
irb(main):011:0> a.object_id
=> -209951576
irb(main):012:0> a = 2**62 -1
=> 4611686018427387903
irb(main):013:0> a.object_id
=> -209925764
irb(main):014:0> a = 2**62
=> 4611686018427387904
irb(main):015:0> a.object_id
=> -209907800
irb(main):016:0> a = 2**62
=> 4611686018427387904
irb(main):017:0> a.object_id
=> -209891900
```

For GNU/Linux armv7l than equal `2^30 - 1` should be stable and be able to use with #hash.

Nowadays, unixtime should be bigger than `2^30 -1`:

irb> Time.parse("2020/07/31 18:30:00+09:00").to_i > 2**30 - 1
=> true

So, we should check to #hash method optimization validity with the following method:

```ruby
        def self.enable_optimize?
          a1 = 2**30 - 1
          a2 = 2**30 - 1
          b1 = 2**62 - 1
          b2 = 2**62 - 1
          (a1.object_id == a2.object_id) && (b1.object_id == b2.object_id)
        end
```

Signed-off-by: Hiroshi Hatake <[email protected]>
@cosmo0920 cosmo0920 self-assigned this Aug 3, 2020
repeatedly added a commit that referenced this issue Aug 4, 2020
…with-hash-method

buffer: Do more precise timekey optimization handling. Fix #3088
@mittyorz
Copy link
Author

mittyorz commented Aug 4, 2020

Many thanks!

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

Successfully merging a pull request may close this issue.

4 participants