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

Buffer's chunk_limit_size not working as expected on Windows platform #2713

Closed
mandyjohar23 opened this issue Dec 4, 2019 · 5 comments · Fixed by #2778
Closed

Buffer's chunk_limit_size not working as expected on Windows platform #2713

mandyjohar23 opened this issue Dec 4, 2019 · 5 comments · Fixed by #2778
Assignees

Comments

@mandyjohar23
Copy link

We are trying to use fluentd on Windows for logs collection, but it seems that buffer section's chunk_limit_size is not working on windows.
Even though chunk_limit_size value is defined as high as 64 MB, fluentd creates a lot of small small chunk files of size 0-1 KB with just 1 log line in each.
Because of this the Windows file descriptors limit(for a process) is reached and then fluentd fails with Error Logs saying not able to write new chunk file and failed to flush the buffer.

Steps to reproduce the behavior:
[Windows] Create a sample log file with significant amount of log lines (say 100k)
Below is a sample from IIS Access Log file used for testing

#Software: Microsoft Internet Information Services 10.0
#Version: 1.0
#Date: 2019-11-19 00:08:21
#Fields: date time s-sitename s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs(User-Agent) cs(Referer) sc-status sc-substatus sc-win32-status sc-bytes cs-bytes time-taken
2019-11-19 00:08:21 W3SVC50001 127.0.0.1 GET /XXXXX/health.html - 50001 - 127.0.0.1 ELB-HealthChecker/2.0 - 200 0 0 311 153 608
2019-11-19 00:08:21 W3SVC50001 ::1 GET /XXXXX/health.html - 50001 - ::1 ELB-HealthChecker/2.0 - 200 0 0 311 153 666
...
around 100k lines

Install td-agent(td-agent-3.5.1-0-x64.msi), configure it using below config file and then start fluentd Service.

Expected behavior:
Fluentd should not create a lot of small small chunk files of size 0-1KB, rather respect the chunk_size_limit value of defined 64MB.

Testing environment:

  • td-agent package version: td-agent-3.5.1-0-x64.msi
  • Operating system: Windows 10 Pro (same behaviour on Windows Server 2016 also)

Test config:

<source>
  @type tail
  path "E:/IntraWeb/logs/IISAccessLog/W3SVC/*.log"
  pos_file "C:\\opt\\td-agent\\pos\\td-agent-iis.pos"
  format /^(?<timestamp>\d+-\d+-\d+\s\d+:\d+:\d+)\s(?<s_sitename>[^\s]*)\s(?<s_ip>[^\s]*)\s(?<cs_method>[^\s]*)\s(?<cs_uri_stem>[^\s]*)\s(?<cs_uri_query>[^\s]*)\s(?<s_port>[^\s]*)\s(?<cs_username>[^\s]*)\s(?<c_ip>[^\s]*)\s(?<cs_user_agent>[^\s]*)\s(?<cs_referer>[^\s]*)\s(?<sc_status>[^\s]*)\s(?<sc_substatus>[^\s]*)\s(?<sc_win32_status>[^\s]*)\s(?<sc_bytes>[^\s]*)\s(?<cs_bytes>[^\s]*)\s(?<time_taken>[^\s]*)?$/
  keep_time_key true
  time_key timestamp
  time_format %Y-%m-%d %H:%M:%S  
  read_from_head true
  limit_recently_modified 3d
  tag xxxx
</source>

<match xxxx>
  @type s3

  aws_key_id xxxx
  aws_sec_key xxxx
  s3_bucket xxxx
  s3_region xxxx

  path xxxx
  s3_object_key_format %{path}%{time_slice}/%{index}.%{file_extension}
  time_slice_format %Y-%m-%d/%H  #%Y%m%d%H
  time_format %Y-%m-%dT%H:%M:%S.%L%z
  format json
  time_key time
  include_time_key true

  <buffer tag,time>
    @type file
    path C:\opt\td-agent\buffer
    timekey 3600 # 1 hour partition
    chunk_limit_size 64MB
    flush_mode interval
    flush_interval 30s
    flush_thread_count 4
    flush_at_shutdown true
  </buffer>

</match>

Error Log:
Within 1-2 sec of starting Fluentd Service, the buffer folder suddenly explodes with 2040 files (buffer.xx.log and buffer.xx.log.meta file combos).
Each of the buffer.xx.log contains only 1 log line event and td-agent log starts showing warn logs stating Can't create new buffer file.

2019-12-04 11:16:35 +0800 [info]: parsing config file is succeeded path="C:/opt/td-agent/etc/td-agent/td-agent.conf"
2019-12-04 11:16:37 +0800 [info]: using configuration file: <ROOT>
  <source>
    @type tail
    path "E:/IntraWeb/logs/IISAccessLog/W3SVC/*.log"
    pos_file "C:\\opt\\td-agent\\pos\\td-agent-iis.pos"
    format /^(?<timestamp>\d+-\d+-\d+\s\d+:\d+:\d+)\s(?<s_sitename>[^\s]*)\s(?<s_ip>[^\s]*)\s(?<cs_method>[^\s]*)\s(?<cs_uri_stem>[^\s]*)\s(?<cs_uri_query>[^\s]*)\s(?<s_port>[^\s]*)\s(?<cs_username>[^\s]*)\s(?<c_ip>[^\s]*)\s(?<cs_user_agent>[^\s]*)\s(?<cs_referer>[^\s]*)\s(?<sc_status>[^\s]*)\s(?<sc_substatus>[^\s]*)\s(?<sc_win32_status>[^\s]*)\s(?<sc_bytes>[^\s]*)\s(?<cs_bytes>[^\s]*)\s(?<time_taken>[^\s]*)?$/
    keep_time_key true
    time_key timestamp
    time_format %Y-%m-%d %H:%M:%S
    read_from_head true
    limit_recently_modified 3d
    tag "xxxx"
    <parse>
      time_key timestamp
      time_format %Y-%m-%d %H:%M:%S
      keep_time_key true
      @type regexp
      expression ^(?<timestamp>\d+-\d+-\d+\s\d+:\d+:\d+)\s(?<s_sitename>[^\s]*)\s(?<s_ip>[^\s]*)\s(?<cs_method>[^\s]*)\s(?<cs_uri_stem>[^\s]*)\s(?<cs_uri_query>[^\s]*)\s(?<s_port>[^\s]*)\s(?<cs_username>[^\s]*)\s(?<c_ip>[^\s]*)\s(?<cs_user_agent>[^\s]*)\s(?<cs_referer>[^\s]*)\s(?<sc_status>[^\s]*)\s(?<sc_substatus>[^\s]*)\s(?<sc_win32_status>[^\s]*)\s(?<sc_bytes>[^\s]*)\s(?<cs_bytes>[^\s]*)\s(?<time_taken>[^\s]*)?$
    </parse>
  </source>
  <filter xxxx>
    @type record_modifier
    <record>
      xxxxxx xxxxxx
      xxxxxx xxxxxx
      time ${record['timestamp']}
    </record>
  </filter>
  <match xxxx>
    @type s3
    aws_key_id xxxxxx
    aws_sec_key xxxxxx
    s3_bucket xxxxxx
    s3_region xxxxxx
    path "xxxxxx/"
    s3_object_key_format "%{path}%{time_slice}/xxxxxx/%{index}.%{file_extension}"
    time_slice_format %Y-%m-%d/%H
    time_format %Y-%m-%dT%H:%M:%S.%L%z
    format json
    time_key time
    include_time_key true
    <buffer tag,time>
      @type "file"
      path "C:\\opt\\td-agent\\buffer"
      timekey 3600
      chunk_limit_size 64MB
      flush_mode interval
      flush_interval 30s
      flush_thread_count 4
      flush_at_shutdown true
    </buffer>
    <format>
      @type json
    </format>
    <inject>
      time_key time
      time_format %Y-%m-%dT%H:%M:%S.%L%z
      time_type string
    </inject>
  </match>
</ROOT>
2019-12-04 11:16:37 +0800 [info]: starting fluentd-1.7.4 pid=5376 ruby="2.4.9"
2019-12-04 11:16:37 +0800 [info]: spawn command to main:  cmdline=["C:/opt/td-agent/embedded/bin/ruby.exe", "-Eascii-8bit:ascii-8bit", "C:/opt/td-agent/embedded/bin/fluentd", "-c", "C:/opt/td-agent/etc/td-agent/td-agent.conf", "-o", "C:/opt/td-agent/td-agent.log", "-x", "fluentdwinsvc", "--under-supervisor"]
2019-12-04 11:16:38 +0800 [info]: gem 'fluent-plugin-elasticsearch' version '3.5.5'
2019-12-04 11:16:38 +0800 [info]: gem 'fluent-plugin-kafka' version '0.12.1'
2019-12-04 11:16:38 +0800 [info]: gem 'fluent-plugin-parser-winevt_xml' version '0.2.0'
2019-12-04 11:16:38 +0800 [info]: gem 'fluent-plugin-prometheus' version '1.7.0'
2019-12-04 11:16:38 +0800 [info]: gem 'fluent-plugin-record-modifier' version '2.0.1'
2019-12-04 11:16:38 +0800 [info]: gem 'fluent-plugin-rewrite-tag-filter' version '2.2.0'
2019-12-04 11:16:38 +0800 [info]: gem 'fluent-plugin-s3' version '1.2.0'
2019-12-04 11:16:38 +0800 [info]: gem 'fluent-plugin-td' version '1.0.0'
2019-12-04 11:16:38 +0800 [info]: gem 'fluent-plugin-td-monitoring' version '0.2.4'
2019-12-04 11:16:38 +0800 [info]: gem 'fluent-plugin-webhdfs' version '1.2.4'
2019-12-04 11:16:38 +0800 [info]: gem 'fluent-plugin-windows-eventlog' version '0.4.3'
2019-12-04 11:16:38 +0800 [info]: gem 'fluentd' version '1.7.4'
2019-12-04 11:16:38 +0800 [info]: adding filter pattern="xxxx" type="record_modifier"
2019-12-04 11:16:38 +0800 [info]: adding match pattern="xxxx" type="s3"
2019-12-04 11:16:39 +0800 [info]: adding source type="tail"
2019-12-04 11:16:39 +0800 [info]: #0 starting fluentd worker pid=9320 ppid=5376 worker=0
2019-12-04 11:16:41 +0800 [info]: #0 following tail of E:/IntraWeb/logs/IISAccessLog/W3SVC/u_ex191128.log
2019-12-04 11:16:41 +0800 [warn]: #0 pattern not matched: "#Software: Microsoft Internet Information Services 10.0"
2019-12-04 11:16:41 +0800 [warn]: #0 pattern not matched: "#Version: 1.0"
2019-12-04 11:16:41 +0800 [warn]: #0 pattern not matched: "#Date: 2019-11-28 01:30:42"
2019-12-04 11:16:41 +0800 [warn]: #0 pattern not matched: "#Fields: date time s-sitename s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs(User-Agent) cs(Referer) sc-status sc-substatus sc-win32-status sc-bytes cs-bytes time-taken"
2019-12-04 11:16:41 +0800 [warn]: #0 pattern not matched: "#Software: Microsoft Internet Information Services 10.0"
2019-12-04 11:16:41 +0800 [warn]: #0 pattern not matched: "#Version: 1.0"
2019-12-04 11:16:41 +0800 [warn]: #0 pattern not matched: "#Date: 2019-11-28 01:47:12"
2019-12-04 11:16:41 +0800 [warn]: #0 pattern not matched: "#Fields: date time s-sitename s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs(User-Agent) cs(Referer) sc-status sc-substatus sc-win32-status sc-bytes cs-bytes time-taken"
2019-12-04 11:16:42 +0800 [warn]: #0 failed to write data into buffer by buffer overflow action=:throw_exception
2019-12-04 11:16:42 +0800 [warn]: #0 emit transaction failed: error_class=Fluent::Plugin::Buffer::BufferOverflowError error="can't create buffer file for C:\\opt\\td-agent\\buffer/buffer.*.log. Stop creating buffer files: error = Too many open files @ rb_sysopen - C:\\opt\\td-agent\\buffer/buffer.b598d83de671a4b73ff303f141c3bfc6f.log" location="C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer/file_chunk.rb:291:in `rescue in create_new_chunk'" tag="xxxx"
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer/file_chunk.rb:291:in `rescue in create_new_chunk'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer/file_chunk.rb:283:in `create_new_chunk'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer/file_chunk.rb:54:in `initialize'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buf_file.rb:173:in `new'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buf_file.rb:173:in `generate_chunk'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer.rb:555:in `block in write_once'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer.rb:555:in `write_once'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer.rb:278:in `block in write'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer.rb:276:in `each'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer.rb:276:in `write'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/output.rb:954:in `block in handle_stream_with_custom_format'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/output.rb:880:in `write_guard'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/output.rb:953:in `handle_stream_with_custom_format'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/output.rb:872:in `execute_chunking'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/output.rb:800:in `emit_buffered'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/event_router.rb:160:in `emit_events'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/event_router.rb:97:in `emit_stream'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:410:in `receive_lines'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:528:in `wrap_receive_lines'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:762:in `block in handle_notify'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:806:in `with_io'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:742:in `handle_notify'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:738:in `block in on_notify'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:738:in `synchronize'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:738:in `on_notify'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:558:in `on_notify'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:532:in `attach'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:281:in `setup_watcher'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:312:in `block in start_watchers'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:298:in `each'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:298:in `start_watchers'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:275:in `refresh_watchers'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:203:in `start'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/root_agent.rb:203:in `block in start'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/root_agent.rb:192:in `block (2 levels) in lifecycle'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/root_agent.rb:191:in `each'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/root_agent.rb:191:in `block in lifecycle'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/root_agent.rb:178:in `each'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/root_agent.rb:178:in `lifecycle'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/root_agent.rb:202:in `start'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/engine.rb:274:in `start'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/engine.rb:219:in `run'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/supervisor.rb:816:in `run_engine'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/supervisor.rb:559:in `block in run_worker'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/supervisor.rb:741:in `main_process'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/supervisor.rb:554:in `run_worker'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/command/fluentd.rb:330:in `<top (required)>'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/site_ruby/2.4.0/rubygems/core_ext/kernel_require.rb:55:in `require'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/site_ruby/2.4.0/rubygems/core_ext/kernel_require.rb:55:in `require'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/bin/fluentd:8:in `<top (required)>'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/bin/fluentd:23:in `load'
  2019-12-04 11:16:42 +0800 [warn]: #0 C:/opt/td-agent/embedded/bin/fluentd:23:in `<main>'
2019-12-04 11:16:42 +0800 [info]: #0 fluentd worker is now running worker=0
2019-12-04 11:16:43 +0800 [warn]: #0 failed to write data into buffer by buffer overflow action=:throw_exception
2019-12-04 11:16:43 +0800 [warn]: #0 emit transaction failed: error_class=Fluent::Plugin::Buffer::BufferOverflowError error="can't create buffer file for C:\\opt\\td-agent\\buffer/buffer.*.log. Stop creating buffer files: error = Too many open files @ rb_sysopen - C:\\opt\\td-agent\\buffer/buffer.b598d83df69790119ca6cba13d84aab66.log" location="C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer/file_chunk.rb:291:in `rescue in create_new_chunk'" tag="xxxx"
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer/file_chunk.rb:291:in `rescue in create_new_chunk'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer/file_chunk.rb:283:in `create_new_chunk'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer/file_chunk.rb:54:in `initialize'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buf_file.rb:173:in `new'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buf_file.rb:173:in `generate_chunk'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer.rb:555:in `block in write_once'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer.rb:555:in `write_once'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer.rb:278:in `block in write'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer.rb:276:in `each'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer.rb:276:in `write'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/output.rb:954:in `block in handle_stream_with_custom_format'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/output.rb:880:in `write_guard'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/output.rb:953:in `handle_stream_with_custom_format'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/output.rb:872:in `execute_chunking'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/output.rb:800:in `emit_buffered'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/event_router.rb:160:in `emit_events'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/event_router.rb:97:in `emit_stream'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:410:in `receive_lines'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:528:in `wrap_receive_lines'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:762:in `block in handle_notify'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:806:in `with_io'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:742:in `handle_notify'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:738:in `block in on_notify'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:738:in `synchronize'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:738:in `on_notify'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:558:in `on_notify'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/in_tail.rb:644:in `on_timer'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/cool.io-1.5.4/lib/cool.io/loop.rb:88:in `run_once'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/cool.io-1.5.4/lib/cool.io/loop.rb:88:in `run'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin_helper/event_loop.rb:93:in `block in start'
  2019-12-04 11:16:43 +0800 [warn]: #0 C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2019-12-04 11:16:44 +0800 [warn]: #0 failed to flush the buffer. retry_time=0 next_retry_seconds=2019-12-04 11:16:45 +0800 chunk="598d83dd34653b8762cfb31e650b22df" error_class=Errno::EMFILE error="Failed to open TCP connection to ac-conversion-log-bucket.s3.ap-northeast-1.amazonaws.com:443 (Too many open files - socket(2) for \"ac-conversion-log-bucket.s3.ap-northeast-1.amazonaws.com\" port 443)"
  ...
  retry log continues from flush buffer

Additional context:
Using same config inside a fluent Debian container fluent/fluentd:v1.7-debian-1 works fine on both Linux and Windows 10 Pro(with linux container support).

Problem happens only while running fluentd directly as a service on Windows or using same config inside a fluent Windows container Windows Server 2016(can't run linux container).

So I suspect there is something wrong specifically with fluent packaging on Windows. Please help!

@mandyjohar23
Copy link
Author

mandyjohar23 commented Dec 4, 2019

Enabling Fluentd Debug logs and re-starting the Fluentd service on Windows also verifies creation of those small sized 1020 buffer chunks of size 0-1 KB each (buffer chunks are created in just 1-2 sec), until fluentd fails to create a new buffer chunk because of system error Stop creating buffer files: error = Too many open files @ rb_sysopen - C:\opt\td-agent\buffer/buffer.b598db0aeee94993f44c0493f7a979962.log" location="C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer/file_chunk.rb:291:in `rescue in create_new_chunk'"

2019-12-04 14:37:05 +0800 [info]: parsing config file is succeeded path="C:/opt/td-agent/etc/td-agent/td-agent.conf"
2019-12-04 14:37:07 +0800 [info]: using configuration file: <ROOT>
<--- config file same as given above --->
2019-12-04 14:37:07 +0800 [info]: starting fluentd-1.7.4 pid=13668 ruby="2.4.9"
2019-12-04 14:37:07 +0800 [info]: spawn command to main:  cmdline=["C:/opt/td-agent/embedded/bin/ruby.exe", "-Eascii-8bit:ascii-8bit", "C:/opt/td-agent/embedded/bin/fluentd", "-c", "C:/opt/td-agent/etc/td-agent/td-agent.conf", "-o", "C:/opt/td-agent/td-agent.log", "-x", "fluentdwinsvc", "--under-supervisor"]
2019-12-04 14:37:08 +0800 [info]: gem 'fluent-plugin-elasticsearch' version '3.5.5'
2019-12-04 14:37:08 +0800 [info]: gem 'fluent-plugin-kafka' version '0.12.1'
2019-12-04 14:37:08 +0800 [info]: gem 'fluent-plugin-parser-winevt_xml' version '0.2.0'
2019-12-04 14:37:08 +0800 [info]: gem 'fluent-plugin-prometheus' version '1.7.0'
2019-12-04 14:37:08 +0800 [info]: gem 'fluent-plugin-record-modifier' version '2.0.1'
2019-12-04 14:37:08 +0800 [info]: gem 'fluent-plugin-rewrite-tag-filter' version '2.2.0'
2019-12-04 14:37:08 +0800 [info]: gem 'fluent-plugin-s3' version '1.2.0'
2019-12-04 14:37:08 +0800 [info]: gem 'fluent-plugin-td' version '1.0.0'
2019-12-04 14:37:08 +0800 [info]: gem 'fluent-plugin-td-monitoring' version '0.2.4'
2019-12-04 14:37:08 +0800 [info]: gem 'fluent-plugin-webhdfs' version '1.2.4'
2019-12-04 14:37:08 +0800 [info]: gem 'fluent-plugin-windows-eventlog' version '0.4.3'
2019-12-04 14:37:08 +0800 [info]: gem 'fluentd' version '1.7.4'
2019-12-04 14:37:08 +0800 [info]: adding filter pattern="xx.xx.xx.xx" type="record_modifier"
2019-12-04 14:37:08 +0800 [info]: adding match pattern="xx.xx.xx.xx" type="s3"
2019-12-04 14:37:09 +0800 [info]: adding source type="tail"
2019-12-04 14:37:09 +0800 [info]: #0 starting fluentd worker pid=3944 ppid=13668 worker=0
2019-12-04 14:37:11 +0800 [debug]: #0 buffer started instance=41980220 stage_size=0 queue_size=0
2019-12-04 14:37:11 +0800 [debug]: #0 flush_thread actually running
2019-12-04 14:37:11 +0800 [debug]: #0 flush_thread actually running
2019-12-04 14:37:11 +0800 [debug]: #0 flush_thread actually running
2019-12-04 14:37:11 +0800 [debug]: #0 flush_thread actually running
2019-12-04 14:37:11 +0800 [debug]: #0 enqueue_thread actually running
2019-12-04 14:37:11 +0800 [debug]: #0 tailing paths: target = E:/IntraWeb/logs/IISAccessLog/W3SVC/u_ex191128.log | existing = 
2019-12-04 14:37:11 +0800 [info]: #0 following tail of E:/IntraWeb/logs/IISAccessLog/W3SVC/u_ex191128.log
2019-12-04 14:37:11 +0800 [warn]: #0 pattern not matched: "#Software: Microsoft Internet Information Services 10.0"
2019-12-04 14:37:11 +0800 [warn]: #0 pattern not matched: "#Version: 1.0"
2019-12-04 14:37:11 +0800 [warn]: #0 pattern not matched: "#Date: 2019-11-28 01:30:42"
2019-12-04 14:37:11 +0800 [warn]: #0 pattern not matched: "#Fields: date time s-sitename s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs(User-Agent) cs(Referer) sc-status sc-substatus sc-win32-status sc-bytes cs-bytes time-taken"
2019-12-04 14:37:11 +0800 [warn]: #0 pattern not matched: "#Software: Microsoft Internet Information Services 10.0"
2019-12-04 14:37:11 +0800 [warn]: #0 pattern not matched: "#Version: 1.0"
2019-12-04 14:37:11 +0800 [warn]: #0 pattern not matched: "#Date: 2019-11-28 01:47:12"
2019-12-04 14:37:11 +0800 [warn]: #0 pattern not matched: "#Fields: date time s-sitename s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs(User-Agent) cs(Referer) sc-status sc-substatus sc-win32-status sc-bytes cs-bytes time-taken"
2019-12-04 14:37:11 +0800 [debug]: #0 Created new chunk chunk_id="598db0adcf723992222b08ecbd1c97d3" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1574874000, tag="xx.xx.xx.xx", variables=nil>
2019-12-04 14:37:11 +0800 [debug]: #0 Created new chunk chunk_id="598db0add1a2e8a957c835db12dd4edc" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1574874000, tag="xx.xx.xx.xx", variables=nil>
2019-12-04 14:37:11 +0800 [debug]: #0 Created new chunk chunk_id="598db0add1e20f12d31ca17ed3cf0e48" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1574874000, tag="xx.xx.xx.xx", variables=nil>
<--------- 1020 log lines with simial debug messages ~Created new chunk chunk_id="xxx --------->
2019-12-04 14:37:12 +0800 [debug]: #0 Created new chunk chunk_id="598db0aeee5638973de4489226d5a449" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1574877600, tag="xx.xx.xx.xx", variables=nil>
2019-12-04 14:37:12 +0800 [warn]: #0 failed to write data into buffer by buffer overflow action=:throw_exception
2019-12-04 14:37:12 +0800 [warn]: #0 emit transaction failed: error_class=Fluent::Plugin::Buffer::BufferOverflowError error="can't create buffer file for C:\\opt\\td-agent\\buffer/buffer.*.log. Stop creating buffer files: error = Too many open files @ rb_sysopen - C:\\opt\\td-agent\\buffer/buffer.b598db0aeee94993f44c0493f7a979962.log" location="C:/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-1.7.4/lib/fluent/plugin/buffer/file_chunk.rb:291:in `rescue in create_new_chunk'" tag="xx.xx.xx.xx"

@en-siba
Copy link

en-siba commented Jan 6, 2020

I was in the same situation.
This can be avoided by downgrading to td-agent-3.4.1-0-x64.msi.

@repeatedly
Copy link
Member

@cosmo0920 Could you check this issue?

@cosmo0920 cosmo0920 self-assigned this Jan 6, 2020
@cosmo0920
Copy link
Contributor

I've reproduced this issue with S3 plugin and minio instead of AWS S3:

<source>
  @type tail
  path "C:/inetpub/logs/LogFiles/W3SVC1/*.log"
  pos_file "C:\\inetpub\\td-agent-iis.pos"
  format /^(?<timestamp>\d+-\d+-\d+\s\d+:\d+:\d+)\s(?<s_ip>[^\s]*)\s(?<cs_method>[^\s]*)\s(?<cs_uri_stem>[^\s]*)\s(?<cs_uri_query>[^\s]*)\s(?<s_port>[^\s]*)\s(?<cs_username>[^\s]*)\s(?<c_ip>[^\s]*)\s(?<cs_user_agent>[^\s]*)\s(?<cs_referer>[^\s]*)\s(?<sc_status>[^\s]*)\s(?<sc_substatus>[^\s]*)\s(?<sc_win32_status>[^\s]*)\s(?<time_taken>[^\s]*)?$/
  tag xxxx
  keep_time_key true
  time_key timestamp
  time_format %Y-%m-%d %H:%M:%S
  read_from_head true
  limit_recently_modified 3d
  tag xxxx
</source>
<filter xxxx>
  @type record_modifier
  <record>
    xxxxxx xxxxxx
    xxxxxx xxxxxx
    time ${record['timestamp']}
  </record>
</filter>

<match xxxx>
  @type s3

  aws_key_id minioadmin
  aws_sec_key minioadmin
  s3_bucket fluentd
  s3_region us-east-1
  s3_endpoint http://192.168.10.19:9000/

  path xxxx
  s3_object_key_format %{path}%{time_slice}/%{index}.%{file_extension}
  time_slice_format %Y-%m-%d/%H  #%Y%m%d%H
  time_format %Y-%m-%dT%H:%M:%S.%L%z
  format json
  time_key time
  include_time_key true
  force_path_style true

  <buffer tag,time>
    @type file
    path C:/opt/td-agent/buffer
    timekey 3600 # 1 hour partition
    chunk_limit_size 64MB
    flush_mode interval
    flush_interval 30s
    flush_thread_count 4
    flush_at_shutdown true
  </buffer>

</match>
PS> C:\opt\td-agent\buffer> ls | wc -l
2041
2020-01-16 15:26:06 +0900 [debug]: #0 fluent/log.rb:302:debug: Created new chunk chunk_id="59c3be671cb73a2fd33010e5b1009623" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1579114800, tag="xxxx", variables=nil>
2020-01-16 15:26:06 +0900 [debug]: #0 fluent/log.rb:302:debug: Created new chunk chunk_id="59c3be671d351d57b46fb6b488b8cdd9" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1579114800, tag="xxxx", variables=nil>
2020-01-16 15:26:06 +0900 [debug]: #0 fluent/log.rb:302:debug: Created new chunk chunk_id="59c3be671d94c08de7179c2716eb388e" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1579114800, tag="xxxx", variables=nil>
2020-01-16 15:26:06 +0900 [warn]: #0 fluent/log.rb:342:warn: failed to write data into buffer by buffer overflow action=:throw_exception
2020-01-16 15:26:06 +0900 [warn]: #0 fluent/log.rb:342:warn: emit transaction failed: error_class=Fluent::Plugin::Buffer::BufferOverflowError error="can't create buffer metadata for C:/opt/td-agent/buffer/buffer.*.log. Stop creating buffer files: error = Too many open files @ rb_sysopen - C:/opt/td-agent/buffer/buffer.b59c3be671e03255959e3f1fc9466e0e1.log.meta" location="C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:309:in `rescue in create_new_chunk'" tag="xxxx"
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:309:in `rescue in create_new_chunk'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:291:in `create_new_chunk'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:52:in `initialize'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buf_file.rb:183:in `new'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buf_file.rb:183:in `generate_chunk'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer.rb:570:in `block in write_once'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Ruby25-x64/lib/ruby/2.5.0/monitor.rb:235:in `mon_synchronize'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer.rb:570:in `write_once'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer.rb:277:in `block in write'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer.rb:275:in `each'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer.rb:275:in `write'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/output.rb:962:in `block in handle_stream_with_custom_format'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/output.rb:888:in `write_guard'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/output.rb:961:in `handle_stream_with_custom_format'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/output.rb:880:in `execute_chunking'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/output.rb:808:in `emit_buffered'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/event_router.rb:160:in `emit_events'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/event_router.rb:97:in `emit_stream'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/in_tail.rb:435:in `receive_lines'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/in_tail.rb:553:in `wrap_receive_lines'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/in_tail.rb:787:in `block in handle_notify'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/in_tail.rb:831:in `with_io'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/in_tail.rb:767:in `handle_notify'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/in_tail.rb:763:in `block in on_notify'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/in_tail.rb:763:in `synchronize'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/in_tail.rb:763:in `on_notify'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/in_tail.rb:583:in `on_notify'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/in_tail.rb:557:in `attach'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/in_tail.rb:306:in `setup_watcher'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/in_tail.rb:337:in `block in start_watchers'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/in_tail.rb:323:in `each'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/in_tail.rb:323:in `start_watchers'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/in_tail.rb:300:in `refresh_watchers'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/in_tail.rb:210:in `start'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/root_agent.rb:200:in `block in start'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/root_agent.rb:189:in `block (2 levels) in lifecycle'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/root_agent.rb:188:in `each'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/root_agent.rb:188:in `block in lifecycle'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/root_agent.rb:175:in `each'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/root_agent.rb:175:in `lifecycle'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/root_agent.rb:199:in `start'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/engine.rb:248:in `start'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/engine.rb:147:in `run'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/supervisor.rb:590:in `block in run_worker'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/supervisor.rb:825:in `main_process'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/supervisor.rb:584:in `run_worker'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/command/fluentd.rb:338:in `<top (required)>'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/bin/fluentd:8:in `require'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/bin/fluentd:8:in `<top (required)>'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/vendor/bundle/ruby/2.5.0/bin/fluentd:23:in `load'
  2020-01-16 15:26:06 +0900 [warn]: #0 plugin/in_tail.rb:435:receive_lines: C:/Users/cosmo/Documents/GitHub/fluentd/vendor/bundle/ruby/2.5.0/bin/fluentd:23:in `<main>'
2020-01-16 15:26:06 +0900 [info]: #0 fluent/log.rb:322:info: fluentd worker is now running worker=0
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: enqueueing all chunks in buffer instance=57207780
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: enqueueing all chunks in buffer instance=57207780
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: enqueueing chunk instance=57207780 metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1579111200, tag="xxxx", variables=nil>
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: enqueueing chunk instance=57207780 metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1579111200, tag="xxxx", variables=nil>
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: enqueueing chunk instance=57207780 metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1579111200, tag="xxxx", variables=nil>
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: enqueueing chunk instance=57207780 metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1579111200, tag="xxxx", variables=nil>
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: dequeueing a chunk instance=57207780
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: chunk dequeued instance=57207780 metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1579111200, tag="xxxx", variables=nil>
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: trying flush for a chunk chunk="59c3be6503feb9a7ee7fa86f6e1289a2"
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: adding write count instance=47983580
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: executing sync write chunk="59c3be6503feb9a7ee7fa86f6e1289a2"
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: dequeueing a chunk instance=57207780
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: chunk dequeued instance=57207780 metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1579111200, tag="xxxx", variables=nil>
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: trying flush for a chunk chunk="59c3be65048743aae3c52942f25a42c9"
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: adding write count instance=47983580
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: executing sync write chunk="59c3be65048743aae3c52942f25a42c9"
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: dequeueing a chunk instance=57207780
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: chunk dequeued instance=57207780 metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1579111200, tag="xxxx", variables=nil>
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: trying flush for a chunk chunk="59c3be6504ebaf21a332bd186e3b0046"
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: dequeueing a chunk instance=57207780
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: chunk dequeued instance=57207780 metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1579111200, tag="xxxx", variables=nil>
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: trying flush for a chunk chunk="59c3be6505341946ac40e30f335f8c8d"
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: adding write count instance=47983580
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: executing sync write chunk="59c3be6505341946ac40e30f335f8c8d"
opening connection to 192.168.10.19:9000...
opening connection to 192.168.10.19:9000...
<- "HEAD /fluentd/xxxx2020-01-16/03/0.gz HTTP/1.1\r\nContent-Type: \r\nAccept-Encoding: \r\nUser-Agent: aws-sdk-ruby3/3.89.1 ruby/2.5.7 x64-mingw32 aws-sdk-s3/1.60.1\r\nHost: 192.168.10.19:9000\r\nX-Amz-Date: 20200116T062607Z\r\nX-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855\r\nAuthorization: AWS4-HMAC-SHA256 Credential=minioadmin/20200116/us-east-1/s3/aws4_request, SignedHeaders=host;user-agent;x-amz-content-sha256;x-amz-date, Signature=d3c552f5095b6b65260423bb4587564c2353406b3417853df2b55dd0e90a6daa\r\nContent-Length: 0\r\nAccept: */*\r\n\r\n"2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: adding write count instance=47983580
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: executing sync write chunk="59c3be6504ebaf21a332bd186e3b0046"
opening connection to 192.168.10.19:9000...

2020-01-16 15:26:07 +0900 [info]: #0 fluent/log.rb:322:info: [Aws::S3::Client 0 0.056638 0 retries] head_object(bucket:"fluentd",key:"xxxx2020-01-16/03/0.gz") Errno::EMFILE Failed to open TCP connection to 192.168.10.19:9000 (Too many open files - socket(2) for "192.168.10.19" port 9000)

2020-01-16 15:26:07 +0900 [debug]: #0 fluent/log.rb:302:debug: taking back chunk for errors. chunk="59c3be6503feb9a7ee7fa86f6e1289a2"
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: taking back a chunk instance=57207780 chunk_id="59c3be6503feb9a7ee7fa86f6e1289a2"
2020-01-16 15:26:07 +0900 [trace]: #0 fluent/log.rb:281:trace: chunk taken back instance=57207780 chunk_id="59c3be6503feb9a7ee7fa86f6e1289a2" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=1579111200, tag="xxxx", variables=nil> 2020-01-16 15:26:07 +0900 [warn]: #0 fluent/log.rb:342:warn: failed to flush the buffer. retry_time=0 next_retry_seconds=2020-01-16 15:26:08 +0900 chunk="59c3be6503feb9a7ee7fa86f6e1289a2" error_class=Errno::EMFILE error="Failed to open TCP connection to 192.168.10.19:9000 (Too many open files - socket(2) for \"192.168.10.19\" port 9000)"
  2020-01-16 15:26:07 +0900 [warn]: #0 plugin/output.rb:1189:rescue in try_flush: C:/Ruby25-x64/lib/ruby/2.5.0/net/http.rb:939:in `rescue in block in connect'
  2020-01-16 15:26:07 +0900 [warn]: #0 plugin/output.rb:1189:rescue in try_flush: C:/Ruby25-x64/lib/ruby/2.5.0/net/http.rb:936:in `block in connect'
  2020-01-16 15:26:07 +0900 [warn]: #0 plugin/output.rb:1189:rescue in try_flush: C:/Ruby25-x64/lib/ruby/2.5.0/timeout.rb:93:in `block in timeout'
  2020-01-16 15:26:07 +0900 [warn]: #0 plugin/output.rb:1189:rescue in try_flush: C:/Ruby25-x64/lib/ruby/2.5.0/timeout.rb:103:in `timeout'
  2020-01-16 15:26:07 +0900 [warn]: #0 plugin/output.rb:1189:rescue in try_flush: C:/Ruby25-x64/lib/ruby/2.5.0/net/http.rb:935:in `connect'
  2020-01-16 15:26:07 +0900 [warn]: #0 plugin/output.rb:1189:rescue in try_flush: C:/Ruby25-x64/lib/ruby/2.5.0/net/http.rb:920:in `do_start'
  2020-01-16 15:26:07 +0900 [warn]: #0 plugin/output.rb:1189:rescue in try_flush: C:/Ruby25-x64/lib/ruby/2.5.0/net/http.rb:915:in `start'
  2020-01-16 15:26:07 +0900 [warn]: #0 plugin/output.rb:1189:rescue in try_flush: C:/Ruby25-x64/lib/ruby/2.5.0/delegate.rb:83:in `method_missing'
  2020-01-16 15:26:07 +0900 [warn]: #0 plugin/output.rb:1189:rescue in try_flush: C:/Users/cosmo/Documents/GitHub/fluentd/vendor/bundle/ruby/2.5.0/gems/aws-sdk-core-3.89.1/lib/seahorse/client/net_http/connection_pool.rb:299:in `start_session'
  2020-01-16 15:26:07 +0900 [warn]: #0 plugin/output.rb:1189:rescue in try_flush: C:/Users/cosmo/Documents/GitHub/fluentd/vendor/bundle/ruby/2.5.0/gems/aws-sdk-core-3.89.1/lib/seahorse/client/net_http/connection_pool.rb:97:in `session_for'   2020-01-16 15:26:07 +0900 [warn]: #0 plugin/output.rb:1189:rescue in try_flush: C:/Users/cosmo/Documents/GitHub/fluentd/vendor/bundle/ruby/2.5.0/gems/aws-sdk-core-3.89.1/lib/seahorse/client/net_http/handler.rb:121:in `session'
  2020-01-16 15:26:07 +0900 [warn]: #0 plugin/output.rb:1189:rescue in try_flush: C:/Users/cosmo/Documents/GitHub/fluentd/vendor/bundle/ruby/2.5.0/gems/aws-sdk-core-3.89.1/lib/seahorse/client/net_http/handler.rb:73:in `transmit'
  2020-01-16 15:26:07 +0900 [warn]: #0 plugin/output.rb:1189:rescue in try_flush: C:/Users/cosmo/Documents/GitHub/fluentd/vendor/bundle/ruby/2.5.0/gems/aws-sdk-core-3.89.1/lib/seahorse/client/net_http/handler.rb:47:in `call'
  2020-01-16 15:26:07 +0900 [warn]: #0 plugin/output.rb:1189:rescue in try_flush: C:/Users/cosmo/Documents/GitHub/fluentd/vendor/bundle/ruby/2.5.0/gems/aws-sdk-core-3.89.1/lib/seahorse/client/plugins/content_length.rb:17:in `call'
  2020-01-16 15:26:07 +0900 [warn]: #0 plugin/output.rb:1189:rescue in try_flush: C:/Users/cosmo/Documents/GitHub/fluentd/vendor/bundle/ruby/2.5.0/gems/aws-sdk-s3-1.60.1/lib/aws-sdk-s3/plugins/s3_signer.rb:111:in `call'
  2020-01-16 15:26:07 +0900 [warn]: #0 plugin/output.rb:1189:rescue in try_flush: C:/Users/cosmo/Documents/GitHub/fluentd/vendor/bundle/ruby/2.5.0/gems/aws-sdk-s3-1.60.1/lib/aws-sdk-s3/plugins/s3_signer.rb:59:in `call'
  2020-01-16 15:26:07 +0900 [warn]: #0 plugin/output.rb:1189:rescue in try_flush: C:/Users/cosmo/Documents/GitHub/fluentd/vendor/bundle/ruby/2.5.0/gems/aws-sdk-s3-1.60.1/lib/aws-sdk-s3/plugins/s3_host_id.rb:15:in `call'
opened
<- "HEAD /fluentd/xxxx2020-01-16/03/0.gz HTTP/1.1\r\nContent-Type: \r\nAccept-Encoding: \r\nUser-Agent: aws-sdk-ruby3/3.89.1 ruby/2.5.7 x64-mingw32 aws-sdk-s3/1.60.1\r\nHost: 192.168.10.19:9000\r\nX-Amz-Date: 20200116T062607Z\r\nX-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855\r\nAuthorization: AWS4-HMAC-SHA256 Credential=minioadmin/20200116/us-east-1/s3/aws4_request, SignedHeaders=host;user-agent;x-amz-content-sha256;x-amz-date, Signature=d3c552f5095b6b65260423bb4587564c2353406b3417853df2b55dd0e90a6daa\r\nContent-Length: 0\r\nAccept: */*\r\n\r\n"2020-01-16 15:26:07 +0900 [info]: #0 fluent/log.rb:322:info: [Aws::S3::Client 0 0.036038 0 retries] head_object(bucket:"fluentd",key:"xxxx2020-01-16/03/0.gz") Errno::EMFILE Failed to open TCP connection to 192.168.10.19:9000 (Too many open files - socket(2) for "192.168.10.19" port 9000)

2020-01-16 15:26:07 +0900 [debug]: #0 fluent/log.rb:302:debug: taking back chunk for errors. chunk="59c3be6504ebaf21a332bd186e3b0046"

@cosmo0920
Copy link
Contributor

I've confirmed that this PR (#2560) is introduced this issue on Windows.

timekey.object_id seems to be differed on Windows.

2020-01-16 16:11:58 +0900 [info]: #0 fluent/log.rb:322:info: [Aws::S3::Client 404 0.081297 0 retries] head_object(bucket:"fluentd",key:"xxxx2020-01-16/03/5.gz") Aws::S3::Errors::NotFound

{:timekey_object_id=>36247560}
{:timekey_object_id=>36247560}
{:timekey_object_id=>38199640}
{:timekey_object_id=>38199640}
{:timekey_object_id=>38199640}
{:timekey_object_id=>38240520}
{:timekey_object_id=>38240520}
{:timekey_object_id=>38240520}
{:timekey_object_id=>38277560}
{:timekey_object_id=>38277560}
{:timekey_object_id=>38277560}
{:timekey_object_id=>38314220}
{:timekey_object_id=>38314220}
{:timekey_object_id=>38314220}
{:timekey_object_id=>40539060}
{:timekey_object_id=>40539060}
{:timekey_object_id=>40539060}
{:timekey_object_id=>40598620}
{:timekey_object_id=>40598620}
{:timekey_object_id=>40598620}
{:timekey_object_id=>40764680}
{:timekey_object_id=>40764680}
{:timekey_object_id=>40764680}
{:timekey_object_id=>40613600}
{:timekey_object_id=>40613600}
{:timekey_object_id=>40613600}
{:timekey_object_id=>40741660}
{:timekey_object_id=>40741660}
{:timekey_object_id=>40741660}
{:timekey_object_id=>40895360}
{:timekey_object_id=>40895360}
{:timekey_object_id=>40895360}
{:timekey_object_id=>40926520}
{:timekey_object_id=>40926520}
{:timekey_object_id=>40926520}
{:timekey_object_id=>41180980}
{:timekey_object_id=>41180980}
{:timekey_object_id=>41180980}
{:timekey_object_id=>40939200}
{:timekey_object_id=>40939200}
{:timekey_object_id=>40939200}
{:timekey_object_id=>41146120}
{:timekey_object_id=>41146120}
{:timekey_object_id=>41146120}
{:timekey_object_id=>41440360}
{:timekey_object_id=>41440360}
{:timekey_object_id=>41440360}
{:timekey_object_id=>41473140}
{:timekey_object_id=>41473140}
{:timekey_object_id=>41473140}
{:timekey_object_id=>41508160}
{:timekey_object_id=>41508160}
{:timekey_object_id=>41508160}
{:timekey_object_id=>41600640}
{:timekey_object_id=>41600640}
{:timekey_object_id=>41600640}
{:timekey_object_id=>41617340}
{:timekey_object_id=>41617340}
{:timekey_object_id=>41617340}
{:timekey_object_id=>41816920}
{:timekey_object_id=>41816920}
{:timekey_object_id=>41816920}
{:timekey_object_id=>41848600}
{:timekey_object_id=>41848600}
{:timekey_object_id=>41848600}
{:timekey_object_id=>41988100}
{:timekey_object_id=>41988100}
{:timekey_object_id=>41988100}
{:timekey_object_id=>42022960}
{:timekey_object_id=>42022960}
{:timekey_object_id=>42022960}
{:timekey_object_id=>42089660}
{:timekey_object_id=>42089660}
{:timekey_object_id=>42089660}
{:timekey_object_id=>42145840}
{:timekey_object_id=>42145840}
{:timekey_object_id=>42145840}
{:timekey_object_id=>42322400}
{:timekey_object_id=>42322400}
{:timekey_object_id=>42322400}
{:timekey_object_id=>42643140}
{:timekey_object_id=>42643140}
{:timekey_object_id=>42643140}
{:timekey_object_id=>42454780}
{:timekey_object_id=>42454780}
{:timekey_object_id=>42454780}
{:timekey_object_id=>42663740}
{:timekey_object_id=>42663740}
{:timekey_object_id=>42663740}
{:timekey_object_id=>42656780}
{:timekey_object_id=>42656780}
{:timekey_object_id=>42656780}
{:timekey_object_id=>42933280}
{:timekey_object_id=>42933280}
{:timekey_object_id=>42933280}
{:timekey_object_id=>27817980}
{:timekey_object_id=>27817980}
{:timekey_object_id=>27817980}
{:timekey_object_id=>28144860}
{:timekey_object_id=>28144860}
{:timekey_object_id=>28144860}
{:timekey_object_id=>28304100}
{:timekey_object_id=>28304100}
{:timekey_object_id=>28304100}
{:timekey_object_id=>28379560}
{:timekey_object_id=>28379560}
{:timekey_object_id=>28379560}
{:timekey_object_id=>28832260}
{:timekey_object_id=>28832260}
{:timekey_object_id=>28832260}
{:timekey_object_id=>29075320}
{:timekey_object_id=>29075320}
{:timekey_object_id=>29075320}
{:timekey_object_id=>30029800}
{:timekey_object_id=>30029800}
{:timekey_object_id=>30029800}
{:timekey_object_id=>30179580}
{:timekey_object_id=>30179580}
{:timekey_object_id=>30179580}
{:timekey_object_id=>30539540}
{:timekey_object_id=>30539540}
{:timekey_object_id=>30539540}
{:timekey_object_id=>32494260}
{:timekey_object_id=>32494260}
{:timekey_object_id=>32494260}
{:timekey_object_id=>27491760}
{:timekey_object_id=>27491760}
{:timekey_object_id=>27491760}
{:timekey_object_id=>27486260}
{:timekey_object_id=>27486260}
{:timekey_object_id=>27486260}
{:timekey_object_id=>34073920}
{:timekey_object_id=>34073920}
{:timekey_object_id=>34073920}
{:timekey_object_id=>34101000}
{:timekey_object_id=>34101000}
{:timekey_object_id=>34101000}
{:timekey_object_id=>34113680}
{:timekey_object_id=>34113680}
{:timekey_object_id=>34113680}
{:timekey_object_id=>34202700}
{:timekey_object_id=>34202700}
{:timekey_object_id=>34202700}
{:timekey_object_id=>34164960}
{:timekey_object_id=>34164960}
{:timekey_object_id=>34164960}
{:timekey_object_id=>34265020}
{:timekey_object_id=>34265020}
{:timekey_object_id=>34265020}
{:timekey_object_id=>34282580}
{:timekey_object_id=>34282580}
{:timekey_object_id=>34282580}
{:timekey_object_id=>34278540}
{:timekey_object_id=>34278540}
{:timekey_object_id=>34278540}
{:timekey_object_id=>34297100}
{:timekey_object_id=>34297100}
{:timekey_object_id=>34297100}
{:timekey_object_id=>34403780}
{:timekey_object_id=>34403780}
{:timekey_object_id=>34403780}
{:timekey_object_id=>34313000}
{:timekey_object_id=>34313000}
{:timekey_object_id=>34313000}
{:timekey_object_id=>34421120}
{:timekey_object_id=>34421120}
{:timekey_object_id=>34421120}
{:timekey_object_id=>34414880}
{:timekey_object_id=>34414880}
{:timekey_object_id=>34414880}
{:timekey_object_id=>27890160}
{:timekey_object_id=>27890160}
{:timekey_object_id=>27890160}
{:timekey_object_id=>28178200}
{:timekey_object_id=>28178200}
{:timekey_object_id=>28178200}
{:timekey_object_id=>28356700}
{:timekey_object_id=>28356700}
{:timekey_object_id=>28356700}
{:timekey_object_id=>28668880}
{:timekey_object_id=>28668880}
{:timekey_object_id=>28668880}
{:timekey_object_id=>28998900}
{:timekey_object_id=>28998900}
{:timekey_object_id=>28998900}
{:timekey_object_id=>30031040}
{:timekey_object_id=>30031040}
{:timekey_object_id=>30031040}
{:timekey_object_id=>30180100}
{:timekey_object_id=>30180100}
{:timekey_object_id=>30180100}
{:timekey_object_id=>30538440}
{:timekey_object_id=>30538440}
{:timekey_object_id=>30538440}
{:timekey_object_id=>32493900}
{:timekey_object_id=>32493900}
{:timekey_object_id=>32493900}
{:timekey_object_id=>27490940}
{:timekey_object_id=>27490940}
{:timekey_object_id=>27490940}
{:timekey_object_id=>34078460}
{:timekey_object_id=>34078460}
{:timekey_object_id=>34078460}
{:timekey_object_id=>34072100}
{:timekey_object_id=>34072100}
{:timekey_object_id=>34072100}
{:timekey_object_id=>34097380}
{:timekey_object_id=>34097380}
{:timekey_object_id=>34097380}
{:timekey_object_id=>34208080}
{:timekey_object_id=>34208080}
{:timekey_object_id=>34208080}
{:timekey_object_id=>34167520}
{:timekey_object_id=>34167520}
{:timekey_object_id=>34167520}
{:timekey_object_id=>34266000}
{:timekey_object_id=>34266000}
{:timekey_object_id=>34266000}
{:timekey_object_id=>34282860}
{:timekey_object_id=>34282860}
{:timekey_object_id=>34282860}
{:timekey_object_id=>34277400}
{:timekey_object_id=>34277400}
{:timekey_object_id=>34277400}
{:timekey_object_id=>34297260}
{:timekey_object_id=>34297260}
{:timekey_object_id=>34297260}
{:timekey_object_id=>34402540}
{:timekey_object_id=>34402540}
{:timekey_object_id=>34402540}
{:timekey_object_id=>34313460}
{:timekey_object_id=>34313460}
{:timekey_object_id=>34313460}
{:timekey_object_id=>34421240}
{:timekey_object_id=>34421240}
{:timekey_object_id=>34421240}
{:timekey_object_id=>34438540}
{:timekey_object_id=>34438540}
{:timekey_object_id=>34438540}
{:timekey_object_id=>34432340}
{:timekey_object_id=>34432340}
{:timekey_object_id=>34432340}
{:timekey_object_id=>34448200}
{:timekey_object_id=>34448200}
{:timekey_object_id=>34448200}
{:timekey_object_id=>34519300}
{:timekey_object_id=>34519300}
{:timekey_object_id=>34519300}
{:timekey_object_id=>34667040}
{:timekey_object_id=>34667040}
{:timekey_object_id=>34667040}
{:timekey_object_id=>35282620}
{:timekey_object_id=>35282620}
{:timekey_object_id=>35282620}
{:timekey_object_id=>35645160}
{:timekey_object_id=>35645160}
{:timekey_object_id=>35645160}
{:timekey_object_id=>35950100}
{:timekey_object_id=>35950100}
{:timekey_object_id=>35950100}
{:timekey_object_id=>36112080}
{:timekey_object_id=>36112080}
{:timekey_object_id=>36112080}
{:timekey_object_id=>37770200}
{:timekey_object_id=>37770200}
{:timekey_object_id=>37770200}
{:timekey_object_id=>38017260}
{:timekey_object_id=>38017260}
{:timekey_object_id=>38017260}
{:timekey_object_id=>38033560}
{:timekey_object_id=>38033560}
{:timekey_object_id=>38033560}
{:timekey_object_id=>38027360}
{:timekey_object_id=>38027360}
{:timekey_object_id=>38027360}
{:timekey_object_id=>38076160}
{:timekey_object_id=>38076160}
{:timekey_object_id=>38076160}
{:timekey_object_id=>38072520}
{:timekey_object_id=>38072520}
{:timekey_object_id=>38072520}
{:timekey_object_id=>38089240}
{:timekey_object_id=>38089240}
{:timekey_object_id=>38089240}
{:timekey_object_id=>38170460}
{:timekey_object_id=>38170460}
{:timekey_object_id=>38170460}
{:timekey_object_id=>38189880}
{:timekey_object_id=>38189880}
{:timekey_object_id=>38189880}
{:timekey_object_id=>38201320}
{:timekey_object_id=>38201320}
{:timekey_object_id=>38201320}
{:timekey_object_id=>38244300}
{:timekey_object_id=>38244300}
{:timekey_object_id=>38244300}
{:timekey_object_id=>38277840}
{:timekey_object_id=>38277840}
{:timekey_object_id=>38277840}
{:timekey_object_id=>38334860}
{:timekey_object_id=>38334860}
{:timekey_object_id=>38334860}
{:timekey_object_id=>40535760}
{:timekey_object_id=>40535760}
{:timekey_object_id=>40535760}
{:timekey_object_id=>40594440}
{:timekey_object_id=>40594440}
{:timekey_object_id=>40594440}
{:timekey_object_id=>40801020}
{:timekey_object_id=>40801020}
{:timekey_object_id=>40801020}
{:timekey_object_id=>40611360}
{:timekey_object_id=>40611360}
{:timekey_object_id=>40611360}
{:timekey_object_id=>40881000}
{:timekey_object_id=>40881000}
{:timekey_object_id=>40881000}
{:timekey_object_id=>40831380}
{:timekey_object_id=>40831380}
{:timekey_object_id=>40831380}
{:timekey_object_id=>40989960}
{:timekey_object_id=>40989960}
{:timekey_object_id=>40989960}
{:timekey_object_id=>40939920}
2020-01-16 16:11:58 +0900 [debug]: #0 fluent/log.rb:302:debug: out_s3: write chunk 59c3c8a3242cdbf4e5591f73c5c2dfda with metadata #<struct Fluent::Plugin::Buffer::Metadata timekey=1579111200, tag="xxxx", variables=nil> to s3://fluentd/xxxx2020-01-16/03/5.gz
{:timekey_object_id=>40939920}
{:timekey_object_id=>40939920}
{:timekey_object_id=>42141200}
{:timekey_object_id=>42141200}
{:timekey_object_id=>42141200}
{:timekey_object_id=>42321960}
{:timekey_object_id=>42321960}
{:timekey_object_id=>42321960}
{:timekey_object_id=>42424460}
{:timekey_object_id=>42424460}
{:timekey_object_id=>42424460}
{:timekey_object_id=>42693960}
{:timekey_object_id=>42693960}
{:timekey_object_id=>42693960}
{:timekey_object_id=>42660500}
{:timekey_object_id=>42660500}
{:timekey_object_id=>42660500}
{:timekey_object_id=>42897780}
{:timekey_object_id=>42897780}
{:timekey_object_id=>42897780}
{:timekey_object_id=>42947580}
{:timekey_object_id=>42947580}
{:timekey_object_id=>42947580}
{:timekey_object_id=>43010120}
{:timekey_object_id=>43010120}
{:timekey_object_id=>43010120}
2020-01-16 16:11:58 +0900 [error]: #0 fluent/log.rb:362:error: unexpected error while checking flushed chunks. ignored. error_class=RuntimeError error="can't enqueue buffer metadata and failed to restore. This may causes inconsistent state: path = C:/opt/td-agent/buffer/buffer.b59c3c8a32649eeaf4366c1b04ba413e6.log.meta, error = 'Too many open files @ rb_sysopen - C:/opt/td-agent/buffer/buffer.q59c3c8a32649eeaf4366c1b04ba413e6.log.meta', retry error = 'closed stream'"
  2020-01-16 16:11:58 +0900 [error]: #0 C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:138:in `rescue in rescue in enqueued!'
  2020-01-16 16:11:58 +0900 [error]: #0 C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:133:in `rescue in enqueued!'
  2020-01-16 16:11:58 +0900 [error]: #0 C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer/file_chunk.rb:130:in `enqueued!'
  2020-01-16 16:11:58 +0900 [error]: #0 C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer.rb:406:in `block (2 levels) in enqueue_chunk'
  2020-01-16 16:11:58 +0900 [error]: #0 C:/Ruby25-x64/lib/ruby/2.5.0/monitor.rb:235:in `mon_synchronize'
  2020-01-16 16:11:58 +0900 [error]: #0 C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer.rb:400:in `block in enqueue_chunk'
  2020-01-16 16:11:58 +0900 [error]: #0 C:/Ruby25-x64/lib/ruby/2.5.0/monitor.rb:235:in `mon_synchronize'
  2020-01-16 16:11:58 +0900 [error]: #0 C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer.rb:399:in `enqueue_chunk'
  2020-01-16 16:11:58 +0900 [error]: #0 C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer.rb:442:in `block in enqueue_all'
  2020-01-16 16:11:58 +0900 [error]: #0 C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer.rb:435:in `each'
  2020-01-16 16:11:58 +0900 [error]: #0 C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/buffer.rb:435:in `enqueue_all'
  2020-01-16 16:11:58 +0900 [error]: #0 C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin/output.rb:1380:in `enqueue_thread_run'
  2020-01-16 16:11:58 +0900 [error]: #0 C:/Users/cosmo/Documents/GitHub/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'

cosmo0920 added a commit that referenced this issue Jan 16, 2020
Because this data will be differed unexpectedly on Windows.
This unexpected differing caused flood of buffer files
due to wrong metadata comparision.
`hash` method inside Metadata struct should be used on non-Windows environment.

This object_id value's unstability is monitored as follows:

```
{:timekey_object_id=>36247560}
{:timekey_object_id=>36247560}
{:timekey_object_id=>38199640}
{:timekey_object_id=>38199640}
{:timekey_object_id=>38199640}
{:timekey_object_id=>38240520}
{:timekey_object_id=>38240520}
{:timekey_object_id=>38240520}
{:timekey_object_id=>38277560}
{:timekey_object_id=>38277560}
{:timekey_object_id=>38277560}
{:timekey_object_id=>38314220}
{:timekey_object_id=>38314220}
{:timekey_object_id=>38314220}
{:timekey_object_id=>40539060}
{:timekey_object_id=>40539060}
{:timekey_object_id=>40539060}
{:timekey_object_id=>40598620}
{:timekey_object_id=>40598620}
{:timekey_object_id=>40598620}
{:timekey_object_id=>40764680}
{:timekey_object_id=>40764680}
{:timekey_object_id=>40764680}
{:timekey_object_id=>40613600}
{:timekey_object_id=>40613600}
{:timekey_object_id=>40613600}
{:timekey_object_id=>40741660}
{:timekey_object_id=>40741660}
{:timekey_object_id=>40741660}
{:timekey_object_id=>40895360}
{:timekey_object_id=>40895360}
{:timekey_object_id=>40895360}
{:timekey_object_id=>40926520}
<snip>
```

Signed-off-by: Hiroshi Hatake <[email protected]>
cosmo0920 added a commit that referenced this issue Jan 17, 2020
…indows

Don't use timekey.object_id for Metadata instance comparison on Windows. Fix #2713
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants