Fluentd: in_tail pos file stops updating after log rotate

[tboothman]

Sometimes (every few weeks) during a log rotation of the file it's tailing fluentd will stop updating its .pos file. Even a day later when the log file rotates again it does not update the pos file.
Even though the pos file is not being updated the file is being consumed and the output is being produced.
The contents of the pos file are a few lines into the new log file and the inode number of the new log file.

The double detected rotation/following tail did not happen on previous days, however I have seen it on another server and it didn't appear to cause a problem that time.

A restart of the service service td-agent restart fixes the problem, but it reads the log from the start, which is less than ideal.

Version: td-agent 2.3.3 x64
OS: Redhat 6.8

/var/log/td-agent/td-agent.log.1

2016-12-20 03:08:03 +0000 [info]: detected rotation of /logs/application.log; waiting 5 seconds
2016-12-20 03:08:03 +0000 [info]: following tail of /logs/application.log
2016-12-20 03:08:03 +0000 [info]: detected rotation of /logs/application.log; waiting 5 seconds
2016-12-20 03:08:03 +0000 [info]: following tail of /logs/application.log
2016-12-20 03:11:37 +0000 [info]: force flushing buffered events

/var/log/td-agent/td-agent.log.2.gz

2016-12-19 03:27:03 +0000 [info]: detected rotation of /logs/application.log; waiting 5 seconds
2016-12-19 03:27:03 +0000 [info]: following tail of /logs/application.log
2016-12-19 03:32:12 +0000 [info]: force flushing buffered events

/var/log/td-agent/application.log.pos:
/logs/application.log 000000000000f16d 00000000000a419e

The pos file last updated on log rotation

ll /var/log/td-agent/application.log.pos
-rw-r--r--. 1 td-agent td-agent   80 Dec 20 03:08 application.log.pos

$ stat /logs/application.log 
  File: `/logs/application.log'
  Size: 2188501633  Blocks: 4274432    IO Block: 4096   regular file
Device: fd00h/64768d    Inode: 672158      Links: 1

strace of the fluentd process

[pid 15119] inotify_add_watch(14, "/logs/application.log", IN_MODIFY|IN_ATTRIB|IN_MOVED_FROM|IN_MOVED_TO|IN_CREATE|IN_DELETE|IN_DELETE_SELF|IN_MOVE_SELF|IN_DONT_FOLLOW|IN_MASK_ADD) = 102215122
[pid 15119] statfs("/logs/application.log", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=5845471, f_bfree=4475644, f_bavail=4177046, f_files=1493280, f_ffree=1288943, f_fsid={-615535995, 789078184}, f_namelen=255, f_frsize=4096}) = 0
[pid 15119] lstat("/logs/application.log", {st_mode=S_IFREG|0644, st_size=2100168079, ...}) = 0
[pid 15119] stat("/logs/application.log", {st_mode=S_IFREG|0644, st_size=2100168079, ...}) = 0
[pid 15119] read(25, "[20/Dec/2016:09:31:59.667731 +00"..., 2048) = 252
[pid 15119] read(25, "", 2048)          = 0
[pid 15119] lseek(25, 0, SEEK_CUR)      = 2100168079
[pid 15119] clock_gettime(CLOCK_MONOTONIC, {4149597, 999687012}) = 0
[pid 15119] epoll_wait(13, {{EPOLLIN, {u32=14, u64=4294967310}}}, 64, 123) = 1
[pid 15119] clock_gettime(CLOCK_MONOTONIC, {4149597, 999728739}) = 0
[pid 15119] read(14, "\321\255\27\6\0\200\0\0\0\0\0\0\0\0\0\0", 287) = 16
[pid 15119] clock_gettime(CLOCK_MONOTONIC, {4149597, 999767484}) = 0
[pid 15119] epoll_wait(13, {{EPOLLIN, {u32=14, u64=4294967310}}}, 64, 123) = 1
[pid 15119] clock_gettime(CLOCK_MONOTONIC, {4149598, 19991561}) = 0
[pid 15119] read(14, "\322\255\27\6\2\0\0\0\0\0\0\0\0\0\0\0", 287) = 16
[pid 15119] lstat("/logs/application.log", {st_mode=S_IFREG|0644, st_size=2100168990, ...}) = 0
[pid 15119] inotify_rm_watch(14, 102215122) = 0

Config:
```

@type tail
format none
path /logs/application.log
pos_file /var/log/td-agent/application.log.pos
tag system.event

@type parser
format /[SYSEVT] (?.+)/
key_name message
suppress_parse_error_log

@type parser
format json
key_name data

@type kafka_buffered
brokers kafka:9092
disable_retry_limit true
flush_interval 1s
compression_codec gzip
exclude_partition_key true
```

[repeatedly]

Could you show me your logrotate config?

[tboothman]

"/logs/application.log" {
  daily
  create 0644 apache root
  rotate 8
  missingok
  compress
  dateext
  notifempty
  sharedscripts
  postrotate
  /sbin/service httpd reload > /dev/null 2>&1 || true; killall -q -USR1 php || true
  endscript
  lastaction
  nice -n15 mv /logs/application.log-*.gz /backup/logs/
  endscript
}

[liujiawinds]

@repeatedly I have the same problem, in_tail doesn't tail log file upon log rotation. After I restart td-agent, all gonna be OK.

versions:

kernel: 2.6.32-431.23.3.el6.x86_64
fluentd: 0.12.29
OS-release: CentOS release 6.5 (Final)
install file: td-agent-2.3.3-0.el6.x86_64.rpm

My in_tail configuration in td-agent.conf

<source>
    type tail
    path /services/logs/*/*.log
    pos_file /var/log/es-applogs.log.pos
    time_format %Y-%m-%d %H:%M:%S.%L
    tag app.*
    format multiline
    format1 /(?<time>\d{4}-\d{1,2}-\d{1,2} \d{1,2}:\d{1,2}:\d{1,2}.\d{3}) \[(?<thread>.*?)\] (?<level>[^\s]+)\s+\[(?<class>.*?):(?<rownum>.*?)\](?<message>.*)/
    read_from_head true
  </source>

log files

ll -i

1884191 -rw-rw-r-- 1 track track  30606891 12月 22 04:37 scorer-error.log
1884183 -rw-rw-r-- 1 track track 291675581 12月 22 04:37 scorer.log

pos file

cat /var/log/es-applogs.log.pos

/services/logs/scorer/scorer.log    0000000000000000    00000000001cc017
/services/logs/scorer/scorer-error.log  0000000000000000    00000000001cc01f

Is there anything helpful to get new log file be tailed?

[repeatedly]

Could you get strace result like tboothman?
And is this problem reproducible?

[repeatedly]

In addition, I want the result of sigdump: http://docs.fluentd.org/articles/trouble-shooting#dump-fluentd-internal-information

[liujiawinds]

  2016-12-23 00:08:05 +0000 [warn]: plugin/in_tail.rb:291:receive_lines: suppressed same stacktrace
2016-12-23 00:08:05 +0000 [warn]: fluent/root_agent.rb:194:handle_emits_error: emit transaction failed: error_class=Fluent::BufferQueueLimitError error="queue size exceeds limit" tag="app.services.logs.scorer.scorer-error.log"
  2016-12-23 00:08:05 +0000 [warn]: plugin/in_tail.rb:291:receive_lines: suppressed same stacktrace
2016-12-23 00:08:05 +0000 [warn]: fluent/root_agent.rb:194:handle_emits_error: emit transaction failed: error_class=Fluent::BufferQueueLimitError error="queue size exceeds limit" tag="app.services.logs.scorer.scorer.log"

I adjusted the arguments buffer_queue_limit to 512, And I'm obeserving it now.

---

Full configuration:

# Do not directly collect fluentd's own logs to avoid infinite loops.
<match fluent.**>
  type null
</match>

<source>
  type tail
  path /services/logs/*/*.log
  pos_file /var/log/es-applogs.log.pos
  time_format %Y-%m-%d %H:%M:%S.%L
  tag app.*
  format multiline
#  With `format_firstline`, in_tail delays record emit until next `format_firstline` matched because in_tail can't judge multiline logs are ended or not without `format_firstline` trigger.
#  format_firstline /\d{4}-\d{1,2}-\d{1,2} \d{1,2}:\d{1,2}:\d{1,2}.\d{3}/
  format1 /(?<time>\d{4}-\d{1,2}-\d{1,2} \d{1,2}:\d{1,2}:\d{1,2}.\d{3}) \[(?<thread>.*?)\] (?<level>[^\s]+)\s+\[(?<class>.*?):(?<rownum>.*?)\](?<message>.*)/
  read_from_head true
</source>


<filter **>
  @type record_transformer
  enable_ruby
  <record>
    hostname "#{Socket.gethostname}"
    service_name ${tag.split('.')[3]}
  </record>
</filter>

<match **>
   type elasticsearch
   log_level info
   include_tag_key true
   host elasticsearch-logging
   port 9200
   logstash_format true
   # Set the chunk limit the same as for fluentd-gcp.
   buffer_chunk_limit 2M
   # Cap buffer memory usage to 2MiB/chunk * 32 chunks = 64 MiB
   buffer_queue_limit 512
   flush_interval 5s
   # Never wait longer than 5 minutes between retries.
   max_retry_wait 30
   # Disable the limit on the number of retries (retry forever).
   disable_retry_limit
   # Use multiple threads for processing.
   num_threads 8
</match>

[repeatedly]

Ah, I see. I assume you have no warnings / errors but pos_file update is stopped.
BTW, BufferQueueLimitError means your output destination lacks the resource or your network environment is unstable.
Please check your environment status.

[tboothman]

Steps to replicate:

config:

<source>
  @type tail
  format none
  path /tmp/application.log
  pos_file /tmp/application.log.pos
  tag stuff
</source>

run this a few times in quick succession (sometimes it works with two after each other, sometimes it takes 10-15, it's some sort of timing issue)

rm -f /tmp/application.log.1;mv /tmp/application.log /tmp/application.log.1; echo 'some stuff' >> /tmp/application.log

Here are the sigdumps of the parent and child process

Sigdump at 2017-01-03 16:21:49 +0000 process 2839 (/usr/sbin/td-agent)
  Thread #<Thread:0x007f275a21a768> status=run priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `dump_backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:34:in `block in dump_all_thread_backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `each'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `dump_all_thread_backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:16:in `block in dump'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `open'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `_open_dump_path'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:14:in `dump'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:7:in `block in setup'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:350:in `call'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:350:in `waitpid'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:350:in `supervise'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:156:in `start'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/command/fluentd.rb:173:in `<top (required)>'
      /opt/td-agent/embedded/lib/ruby/site_ruby/2.1.0/rubygems/core_ext/kernel_require.rb:54:in `require'
      /opt/td-agent/embedded/lib/ruby/site_ruby/2.1.0/rubygems/core_ext/kernel_require.rb:54:in `require'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/bin/fluentd:5:in `<top (required)>'
      /opt/td-agent/embedded/bin/fluentd:23:in `load'
      /opt/td-agent/embedded/bin/fluentd:23:in `<top (required)>'
      /usr/sbin/td-agent:7:in `load'
      /usr/sbin/td-agent:7:in `<main>'
  GC stat:
      count: 19
      heap_used: 261
      heap_length: 261
      heap_increment: 0
      heap_live_slot: 59121
      heap_free_slot: 47262
      heap_final_slot: 0
      heap_swept_slot: 61105
      heap_eden_page_length: 261
      heap_tomb_page_length: 0
      total_allocated_object: 370426
      total_freed_object: 311305
      malloc_increase: 44720
      malloc_limit: 16777216
      minor_gc_count: 14
      major_gc_count: 5
      remembered_shady_object: 677
      remembered_shady_object_limit: 880
      old_object: 39925
      old_object_limit: 69052
      oldmalloc_increase: 3040648
      oldmalloc_limit: 16777216
  Built-in objects:
   106,383: TOTAL
    47,172: FREE
    27,508: T_STRING
    13,190: T_NODE
     7,610: T_ARRAY
     5,368: T_DATA
     2,016: T_CLASS
     1,956: T_OBJECT
       591: T_HASH
       495: T_REGEXP
       137: T_MODULE
       129: T_ICLASS
        78: T_MATCH
        59: T_RATIONAL
        37: T_STRUCT
        23: T_FILE
         9: T_FLOAT
         4: T_BIGNUM
         1: T_COMPLEX

Sigdump at 2017-01-03 16:21:51 +0000 process 2842 (/usr/sbin/td-agent)
  Thread #<Thread:0x007f275a21a768> status=run priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `dump_backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:34:in `block in dump_all_thread_backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `each'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `dump_all_thread_backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:16:in `block in dump'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `open'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `_open_dump_path'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:14:in `dump'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:7:in `block in setup'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `call'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run_once'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/engine.rb:199:in `run'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:570:in `run_engine'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:162:in `block in start'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:366:in `call'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:366:in `main_process'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:339:in `block in supervise'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:338:in `fork'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:338:in `supervise'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:156:in `start'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/command/fluentd.rb:173:in `<top (required)>'
      /opt/td-agent/embedded/lib/ruby/site_ruby/2.1.0/rubygems/core_ext/kernel_require.rb:54:in `require'
      /opt/td-agent/embedded/lib/ruby/site_ruby/2.1.0/rubygems/core_ext/kernel_require.rb:54:in `require'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/bin/fluentd:5:in `<top (required)>'
      /opt/td-agent/embedded/bin/fluentd:23:in `load'
      /opt/td-agent/embedded/bin/fluentd:23:in `<top (required)>'
      /usr/sbin/td-agent:7:in `load'
      /usr/sbin/td-agent:7:in `<main>'
  Thread #<Thread:0x007f27558ab1b8> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run_once'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:275:in `run'
  GC stat:
      count: 21
      heap_used: 261
      heap_length: 261
      heap_increment: 0
      heap_live_slot: 75482
      heap_free_slot: 30901
      heap_final_slot: 0
      heap_swept_slot: 45113
      heap_eden_page_length: 261
      heap_tomb_page_length: 0
      total_allocated_object: 480981
      total_freed_object: 405499
      malloc_increase: 177520
      malloc_limit: 16777216
      minor_gc_count: 16
      major_gc_count: 5
      remembered_shady_object: 1363
      remembered_shady_object_limit: 880
      old_object: 48633
      old_object_limit: 69052
      oldmalloc_increase: 7907304
      oldmalloc_limit: 16777216
  Built-in objects:
   106,383: TOTAL
    32,406: T_STRING
    30,811: FREE
    14,317: T_NODE
    10,340: T_ARRAY
    10,296: T_DATA
     3,273: T_OBJECT
     2,355: T_CLASS
     1,216: T_HASH
       561: T_REGEXP
       167: T_STRUCT
       153: T_ICLASS
       149: T_MODULE
       148: T_MATCH
       115: T_FILE
        59: T_RATIONAL
         9: T_FLOAT
         7: T_BIGNUM
         1: T_COMPLEX

[repeatedly]

Second sigdump result is the case which pos_file is not updated, right?

[tboothman]

Yes, that's the worker/child process

[dennusb]

Any update on this? We are having the same issue at our environments...

[dennusb]

Any updates on this?

[tboothman]

Sadly we just ended up restarting td-agent shortly after the logrotate that sometimes breaks it.

[knockubo]

I tried "Steps to replicate:" tboothman posted.

td-agent-2.3.2-0.el2016.x86_64

This case occur the problem.(pos_file is never updated after this.)

rm -f /tmp/application.log.1;mv /tmp/application.log /tmp/application.log.1;echo 'some stuff' >> /tmp/application.log;

And /var/log/td-agent.log is bellow. "detected rotation.." appeared 3 times.

2017-06-06 11:15:39 +0000 [info]: detected rotation of /tmp/application.log; waiting 5 seconds
2017-06-06 11:15:39 +0000 [info]: following tail of /tmp/application.log
2017-06-06 11:15:39 +0000 [info]: detected rotation of /tmp/application.log; waiting 5 seconds
2017-06-06 11:15:39 +0000 [info]: following tail of /tmp/application.log
2017-06-06 11:15:39 +0000 [info]: detected rotation of /tmp/application.log; waiting 5 seconds
2017-06-06 11:15:39 +0000 [info]: following tail of /tmp/application.log

but This case didn't occur the problem. (touch file after mv. and write to file.)

rm -f /tmp/application.log.1;mv /tmp/application.log /tmp/application.log.1; touch /tmp/application.log; echo 'some stuff' >> /tmp/application.log;

And "detected rotation.." appeared only 1 times.

Sorry I have no ability to fix it..

[cosmo0920]

I've confirmed that this issue couldn't reproduce on macOS 10.12.5 and Fluentd v0.12.36, but it reproduced on Debian Stretch 9.0 RC and Fluentd v0.12.36.
I couldn't reproduce this issue with Fluentd v0.14 for now.

[rgarcia]

We are seeing this in our environment as well

[cosmo0920]

@rgarcia Could you explain your environment details?
Are you using td-agent2 or Fluentd v0.12 directly?

[rgarcia]

Fluentd v0.12 directly via the official docker Debian image

[okkez]

I've tested on my environment and reproduced with following script.
This script can reproduce this issue sometimes.

#!/bin/bash

while true; do
    rm -f /tmp/application.log.1
    mv /tmp/application.log /tmp/application.log.1
    touch /tmp/application.log
    t=$(date +%s.%N)
    echo "some stuff ${t}" >> /tmp/application.log
    inode1=$(cat /tmp/application.log.pos | cut -f 3)
    inode2=$(stat /tmp/application.log | ruby -e 'puts ARGF.read[/Inode:\s*(\d+)/, 1].to_i.to_s(16)')

    echo $inode1 $inode2 $t
    if [ $inode1 != "0000000000${inode2}" ]; then
        exit
    fi
    #sleep 0.5
done

I guess the cause of issue is race condition of StatWatcher.
There are 3 events when run sequence at once (in a few milliseconds). https://github.com/fluent/fluentd/issues/1383#issuecomment-306456252

1. Move log file (IN_MOVE_SELF)
2. Create log file (IN_CREATE)
3. Modify log file (IN_MODIFY)

These events invokes StatWatcher#on_change, TailWatcher#on_rotate and TailWatcher#swap_state.

TailWatcher#swap_state swaps MemoryPositionEntry that have same information (different instance) when position file is not updated.

[repeatedly]

Does someone check okkez's patch? > https://github.com/fluent/fluentd/pull/1598

[knockubo]

Sorry at my env only, I patched to in_tail of fluentd-0.12.26.
and issue fixed.

/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/plugin/in_tail.rb

bash-4.2# diff -u in_tail.rb.org in_tail.rb
--- in_tail.rb.org  2016-07-08 06:22:47.000000000 +0000
+++ in_tail.rb  2017-06-15 03:10:01.303416146 +0000
@@ -453,11 +453,13 @@
               io_handler = IOHandler.new(io, @pe, @log, @read_lines_limit, &method(:wrap_receive_lines))
               @io_handler = io_handler
             else # file is rotated and new file found
+              detach
               @update_watcher.call(@path, swap_state(@pe))
             end
           else # file is rotated and new file not found
             # Clear RotateHandler to avoid duplicated file watch in same path.
             @rotate_handler = nil
+            detach
             @update_watcher.call(@path, swap_state(@pe))
           end
         end
bash-4.2#

Above environment that I tried reproduce is AmazonLinux Container on Docker for Mac.

docker run --name temp-td-agent-test -it amazonlinux /bin/bash

# at other terminal
docker cp td-agent-2.3.2-0.el2016.x86_64.rpm temp-td-agent-test:/

# in container
yum -y install initscripts redhat-lsb-core
rpm -ivh /td-agent-2.3.2-0.el2016.x86_64.rpm

# and done "Steps to replicate:"

The actual Issue is occuring on EC2(AmazonLinux) on AWS with td-agent-2.3.2-0.el2016.x86_64.rpm(fluentd-0.12.26) in my case.

[okkez]

I've tried reproduce sequence in my comment https://github.com/fluent/fluentd/issues/1383#issuecomment-307984033 on EC2 t2.micro instance with Ruby 2.4.1 and #1598 .
I could not reproduce the issue.

I think AmazonLinux Container on Docker for Mac is slower than EC2 t2.micro instance.
So #1598 will fix the actual issue on your EC2 instance.

[repeatedly]

Released v0.12.37 with #1598 fix. Close the issue.