[in_tail] when watched files are deleted, logged Error: undefined method `pe=' for #<Fluent::TailInput::TailWatcher::NullIOHandler #920

tako774 · 2016-04-27T05:52:18Z

On Windows, in_tail plugin causes error when watched files are deleted.
Error message is like below.

undefined method `pe=' for #<Fluent::TailInput::TailWatcher::NullIOHandler:::0x0000000XXXXXXXX>"`

(I have not tested on Linux, so I can't say it is OK on Linux...)

Steps to Reproduce

start fluentd with using in_tail
make a watched file
write "hoge" to the file and save
delete file on Windows Explorer

fluentd or td-agent version.

both of them

fluentd.0.14.0.pre.1 revision: @c874f9521b0679c8cd4f1853002dcab6b422c454 (clone on Apr 27)
fluentd.0.14.0.pre.1 revision: @aa9b87d931be2b014a86c5aa87ecf0bdddef7351 (clone on Mar 7)
it doesn't reproduce with 0.14.0.pre.1 from rubygems.org

Environment information, e.g. OS.

OS: Windows 2012
Ruby: 2.2.4 x64 (Rubyinstaller)

Configuration and Logs

It is at revision @c874f9521b0679c8cd4f1853002dcab6b422c454 log.

2016-04-27 14:23:27 +0900 [info]: reading config file path=".\\fluent.conf"
2016-04-27 14:23:27 +0900 [info]: starting fluentd-0.14.0.pre.1
2016-04-27 14:23:27 +0900 [info]: spawn command to main (windows) : C:/app/Ruby22-x64/bin/ruby.exe 'C:/app/Ruby22-x64/bin/fluentd' -c .\fluent.conf -o fluentd.log --no-supervisor
2016-04-27 14:23:28 +0900 [info]: reading config file path=".\\fluent.conf"
2016-04-27 14:23:28 +0900 [info]: starting fluentd-0.14.0.pre.1 without supervision
2016-04-27 14:23:28 +0900 [debug]: install_main_process_winsigint_handler***** installed main winsiginthandler
2016-04-27 14:23:28 +0900 [info]: gem 'fluentd' version '0.14.0.pre.1'
2016-04-27 14:23:28 +0900 [info]: adding match pattern="**" type="stdout"
2016-04-27 14:23:28 +0900 [info]: adding source type="tail"
2016-04-27 14:23:28 +0900 [info]: using configuration file: <ROOT>
  <system>
    log_level debug
  </system>
  <source>
    @type tail
    @id tail
    path "C:\\app\\fluentd\\test.log"
    tag "test.log"
    format none
    pos_file "test.pos"
    read_from_head true
  </source>
  <match **>
    @type stdout
  </match>
</ROOT>
2016-04-27 14:23:35 +0900 [info]: following tail of C:\app\fluentd\test.log
2016-04-27 14:23:35 +0900 fluent.info: {"message":"following tail of C:\\app\\fluentd\\test.log"}
2016-04-27 14:23:40 +0900 test.log: {"message":"hoge"}
2016-04-27 14:23:44 +0900 [info]: detected rotation of C:\app\fluentd\test.log; waiting 5 seconds
2016-04-27 14:23:44 +0900 fluent.info: {"message":"detected rotation of C:\\app\\fluentd\\test.log; waiting 5 seconds"}
2016-04-27 14:23:50 +0900 [info]: detected rotation of C:\app\fluentd\test.log
2016-04-27 14:23:50 +0900 [error]: undefined method `pe=' for #<Fluent::TailInput::TailWatcher::NullIOHandler:0x000000027030d0>
  2016-04-27 14:23:50 +0900 [error]: C:/app/Ruby22-x64/lib/ruby/gems/2.2.0/gems/fluentd-0.14.0.pre.1/lib/fluent/plugin/in_tail.rb:481:in `swap_state'
  2016-04-27 14:23:50 +0900 [error]: C:/app/Ruby22-x64/lib/ruby/gems/2.2.0/gems/fluentd-0.14.0.pre.1/lib/fluent/plugin/in_tail.rb:471:in `on_rotate'
  2016-04-27 14:23:50 +0900 [error]: C:/app/Ruby22-x64/lib/ruby/gems/2.2.0/gems/fluentd-0.14.0.pre.1/lib/fluent/plugin/in_tail.rb:639:in `call'
  2016-04-27 14:23:50 +0900 [error]: C:/app/Ruby22-x64/lib/ruby/gems/2.2.0/gems/fluentd-0.14.0.pre.1/lib/fluent/plugin/in_tail.rb:639:in `on_notify'
  2016-04-27 14:23:50 +0900 [error]: C:/app/Ruby22-x64/lib/ruby/gems/2.2.0/gems/fluentd-0.14.0.pre.1/lib/fluent/plugin/in_tail.rb:406:in `on_notify'
  2016-04-27 14:23:50 +0900 [error]: C:/app/Ruby22-x64/lib/ruby/gems/2.2.0/gems/fluentd-0.14.0.pre.1/lib/fluent/plugin/in_tail.rb:494:in `call'
  2016-04-27 14:23:50 +0900 [error]: C:/app/Ruby22-x64/lib/ruby/gems/2.2.0/gems/fluentd-0.14.0.pre.1/lib/fluent/plugin/in_tail.rb:494:in `on_timer'
  2016-04-27 14:23:50 +0900 [error]: C:/app/Ruby22-x64/lib/ruby/gems/2.2.0/gems/cool.io-1.4.3/lib/cool.io/loop.rb:88:in `run_once'
  2016-04-27 14:23:50 +0900 [error]: C:/app/Ruby22-x64/lib/ruby/gems/2.2.0/gems/cool.io-1.4.3/lib/cool.io/loop.rb:88:in `run'
  2016-04-27 14:23:50 +0900 [error]: C:/app/Ruby22-x64/lib/ruby/gems/2.2.0/gems/fluentd-0.14.0.pre.1/lib/fluent/plugin/in_tail.rb:264:in `run'
2016-04-27 14:23:50 +0900 fluent.info: {"message":"detected rotation of C:\\app\\fluentd\\test.log"}
2016-04-27 14:23:50 +0900 fluent.error: {"message":"undefined method `pe=' for #<Fluent::TailInput::TailWatcher::NullIOHandler:0x000000027030d0>"}

The text was updated successfully, but these errors were encountered:

repeatedly · 2016-05-09T00:28:53Z

We changed in_tail mechanizm in #788 and #811.
If you have a time, could you check these commits affect this issue or not?

tako774 · 2016-05-13T15:48:04Z

I confirmed this occurs at current master branch on my windows10 PC with Ruby2.2.

Then I unmerged #788 (@64c5d0c) from in_tail by text editor, it didn't reproduce.
Maybe change in #788 affects this issue.

Finally, I unmerge this section from current master, it didn't reproduce.

  -        io = FileWrapper.open(@path)
  -        stat = io.stat
  +       stat = FileWrapper.stat(@path)

open -> stat is good, but stat only is bad, maybe...

repeatedly · 2016-05-18T07:30:36Z

Thanks for the investigation!

@nurse Do you know why this situation happens? open and stat have different error handling?

nurse · 2016-05-19T13:20:44Z

FileWrapper.open keeps given file opening forever, but FileWrapper.stat closes the file after create stat object.
By keeping the file open, it can't be deleted (or deleted from explorer but still exist on filesystem like Unix; this depends FILE_SHARE_DELETE flag).

repeatedly · 2016-05-29T09:44:34Z

@nurse Do you have a good idea to resole this problem? Keeping same behaviour with Linux is better.

nurse · 2016-05-30T03:28:07Z

I don't understand why above difference affect this issue.

tako774 · 2016-05-31T14:10:34Z

I explored this issue with pry.

io = FileWrapper.open(@path) -> stat = io.stat pattern sequence

"make file"
=> inode = <file index no.>, size = <file size> from stat = io.stat
"delete file"
=> io = FileWrapper.open(@path) throws Errno::ENOENT
=> inode = nil, size = 0 from stat = io.stat
=> inode is changed, so on_rotate is called
=> logs detected rotation; wait 5 seconds
=> @rotate_handler = nil is executed

stat = FileWrapper.stat(@path) pattern sequence

"make file"
=> inode = <file index no.>, size = <file size> from stat = FileWrapper.stat(@path)
"delete file"
=> stat = FileWrapper.stat(@path) does not throws Errno::ENOENT
=> inode = 3484713384184393820 (=0x305c305c305c305c), size = file size from stat = FileWrapper.stat(@path)
=> inode is changed, so on_rotate is called
=> logs detected rotation; wait 5 seconds
=> @rotate_handler = nil is executed

=> `on_notify` is called in `on_rotate` > `update_watcher` > `setup_watcher` > `attach(loop)`

=> in on_notify, @inode = nil and @fsize = -1, but inode = 3484713384184393820, size = file size
=> then on_rotate is called (2nd time), and @io_handler is nil, so @io_handler = NullIOHandler.new is executed.
on_notify, next~before 5 seconds elapse after No.6
=> inode and size not changed from No.5.
on_notify, more than 5 seconds elapsed after No.6
=> stat = FileWrapper.stat(@path) throws exception Errno::ENOENT
=> inode = nil, size = 0
=> inode is changed, so on_rotate is called (3rd time)
=> logs detected rotation
=> undefined methodpe=' for #<Fluent::TailInput::TailWatcher::NullIOHandleroccurs inon_rotate>swap_state>@io_handler.pe`

tako774 · 2016-05-31T14:22:56Z

Maybe, fluentd expects FileWrapper.stat throws Errno::ENOENT, but it successfully returns with inode = 3484713384184393820 (=0x305c305c305c305c).

In FileWrapper.stat, GetFileInformationByHandle is called.
https://msdn.microsoft.com/ja-jp/library/cc429317.aspx
When file deleted at stat = FileWrapper.stat(@path) pattern, GetFileInformationByHandle returns 0x305c * 18.

nurse · 2016-05-31T19:14:33Z

As far as I checked, FileWrapper.stat(nonexistent) raised Errno::ENOENT as expected because the begginng of FileWrapper.stat calls File.stat(nonexistent_path), which raises Errno::ENOENT.
Even if it may raise other than Errno::ENOENT, when the path is invalid (EINVAL) or it doesn't have permission...

tako774 · 2016-06-09T14:46:25Z

FileWrapper.stat doesn't raise Errno::ENOENT or other exceptions only in 5 seconds from when the file is deleted (with explorer, cmd and so on) to when 5 seconds elapsed after "detected rotation; wait 5 seconds". After 5 seconds elapsed, FileWrapper.stat raises Errno::ENOENT as expected.

In that 5 seconds, deleted file can be seen from explorer or dir, but to open or access to the security descriptor by cacls is blocked with permission error.

FileWrapper.stat(deleted_but_existing_file_path) raises no exception, so this issue happens.

nurse · 2016-06-10T09:08:18Z

Thank your for inspection.

FileWrapper.stat doesn't raise Errno::ENOENT or other exceptions only in 5 seconds from when the file is deleted (with explorer, cmd and so on) to when 5 seconds elapsed after "detected rotation; wait 5 seconds". After 5 seconds elapsed, FileWrapper.stat raises Errno::ENOENT as expected.

Ah, it seems because of Lazy Write Back of Windows.
In that case, is it always returns 0x305c305c305c305c?
If so it can be avoided by following patch:

diff --git a/lib/fluent/plugin/file_wrapper.rb b/lib/fluent/plugin/file_wrapper.rb
index b6ecd41..6a7a39c 100644
--- a/lib/fluent/plugin/file_wrapper.rb
+++ b/lib/fluent/plugin/file_wrapper.rb
@@ -107,7 +107,11 @@ def ino
         return 0
       end

-      by_handle_file_information.unpack("I11Q1")[11] # fileindex
+      fileindex = by_handle_file_information.unpack("I11Q1")[11]
+      if fileindex == 0x305c305c305c305c
+        raise  Errno::ENOENT, @path
+      end
+      fileindex
     end

     def stat

tako774 · 2016-06-10T13:12:49Z

I checked with 32bit ruby (2.2.4p230 (2015-12-16 revision 53155) [i386-mingw32]), this issue does not happen.

Difference between 32bit and 64bit occurs in code of `WindowsFile.initialize' showed below.

      @file_handle = CreateFile.call(@path, access, sharemode,
                     0, creationdisposition, FILE_ATTRIBUTE_NORMAL, 0)
      if @file_handle == INVALID_HANDLE_VALUE
        err = GetLastError.call
        if err == ERROR_FILE_NOT_FOUND || err == ERROR_ACCESS_DENIED
          raise SystemCallError.new(2)
        end
        raise SystemCallError.new(err)
      end

When @path is deleted but existing file path,

with 32bit ruby: @file_handle = 0xFFFFFFFF, so @file_handle == INVALID_HANDLE_VALUE is satisfied and GetLastError.call returns 5, so err == ERROR_ACCESS_DENIED is staisfied. Then it does raise SystemCallError.new(2).
with 64bit ruby: @file_handle = 0xFFFFFFFFFFFFFFFF, so no error raised here.

I replaced all INVALID_HANDLE_VALUE to INVALID_HANDLE_VALUE64 and add INVALID_HANDLE_VALUE64 = 0xFFFFFFFFFFFFFFFF, then 64bit version works as 32bit.
But I don't know what is the best way to check invalid file handle with 64bit ruby (to check first 4 bytes, or last 4 bytes or all 8 bytes, or other ways...).

tako774 · 2016-06-10T16:12:29Z

In windows-pr library CreateFile is defined as return value L = Long
https://github.com/djberg96/windows-pr/blob/windows-pr-1.2.4/lib/windows/file.rb#L206

API.new('CreateFile', 'SLLPLLL', 'L')

Though INVALID_FILE_HANDLE is defined 0xFFFFFFFF.
https://github.com/djberg96/windows-pr/blob/windows-pr-1.2.4/lib/windows/handle.rb#L12

INVALID_HANDLE_VALUE = 0xFFFFFFFF

In 64bit environment it causes problem.

nurse · 2016-06-13T09:05:24Z

Hmm, it sounds windows-pr's issue. On mswin64, it must define INVALID_HANDLE_VALUE as 0xFFFFFFFFFFFFFFFF.

repeatedly · 2016-06-21T20:00:47Z

After released new windows-pr, I will close this issue.

cosmo0920 · 2016-06-22T05:34:55Z

I've released windows-pr 1.2.5.
Please confirm this issue has been fixed.

tako774 · 2016-06-22T14:21:58Z

I updated window-pr and confirmed this issue didn't happen with both ruby2.2.4 x86/x64 for the scenario which is 2 times loop of make file -> delete file.
Thanks for your great job! 👍🐱👍

Update windows-pr lowest dependency to 1.2.5. fix #920

repeatedly · 2016-06-23T06:35:43Z

I updated dependency version to v1.2.5.
Thanks for hard work!!

repeatedly self-assigned this Apr 27, 2016

repeatedly added the bug Something isn't working label Apr 27, 2016

cosmo0920 mentioned this issue Jun 14, 2016

INVALID_FILE_HANDLE is incorrect in 64bit Windows cosmo0920/windows-pr#13

Closed

repeatedly closed this as completed in 822dee1 Jun 23, 2016

repeatedly added a commit that referenced this issue Jun 23, 2016

Merge pull request #1065 from fluent/update-windows-pr-dependency

17cec5b

Update windows-pr lowest dependency to 1.2.5. fix #920

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[in_tail] when watched files are deleted, logged Error: undefined method `pe=' for #<Fluent::TailInput::TailWatcher::NullIOHandler #920

[in_tail] when watched files are deleted, logged Error: undefined method `pe=' for #<Fluent::TailInput::TailWatcher::NullIOHandler #920

tako774 commented Apr 27, 2016

repeatedly commented May 9, 2016

tako774 commented May 13, 2016 •

edited

Loading

repeatedly commented May 18, 2016

nurse commented May 19, 2016

repeatedly commented May 29, 2016

nurse commented May 30, 2016

tako774 commented May 31, 2016 •

edited

Loading

tako774 commented May 31, 2016 •

edited

Loading

nurse commented May 31, 2016

tako774 commented Jun 9, 2016 •

edited

Loading

nurse commented Jun 10, 2016

tako774 commented Jun 10, 2016 •

edited

Loading

tako774 commented Jun 10, 2016 •

edited

Loading

nurse commented Jun 13, 2016

repeatedly commented Jun 21, 2016

cosmo0920 commented Jun 22, 2016

tako774 commented Jun 22, 2016 •

edited

Loading

repeatedly commented Jun 23, 2016

[in_tail] when watched files are deleted, logged Error: undefined method `pe=' for #<Fluent::TailInput::TailWatcher::NullIOHandler #920

[in_tail] when watched files are deleted, logged Error: undefined method `pe=' for #<Fluent::TailInput::TailWatcher::NullIOHandler #920

Comments

tako774 commented Apr 27, 2016

Steps to Reproduce

fluentd or td-agent version.

Environment information, e.g. OS.

Configuration and Logs

repeatedly commented May 9, 2016

tako774 commented May 13, 2016 • edited Loading

repeatedly commented May 18, 2016

nurse commented May 19, 2016

repeatedly commented May 29, 2016

nurse commented May 30, 2016

tako774 commented May 31, 2016 • edited Loading

tako774 commented May 31, 2016 • edited Loading

nurse commented May 31, 2016

tako774 commented Jun 9, 2016 • edited Loading

nurse commented Jun 10, 2016

tako774 commented Jun 10, 2016 • edited Loading

tako774 commented Jun 10, 2016 • edited Loading

nurse commented Jun 13, 2016

repeatedly commented Jun 21, 2016

cosmo0920 commented Jun 22, 2016

tako774 commented Jun 22, 2016 • edited Loading

repeatedly commented Jun 23, 2016

tako774 commented May 13, 2016 •

edited

Loading

tako774 commented May 31, 2016 •

edited

Loading

tako774 commented May 31, 2016 •

edited

Loading

tako774 commented Jun 9, 2016 •

edited

Loading

tako774 commented Jun 10, 2016 •

edited

Loading

tako774 commented Jun 10, 2016 •

edited

Loading

tako774 commented Jun 22, 2016 •

edited

Loading