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

When the input file is moved, do not set @reopen_on_eof right away. #23

Merged
merged 1 commit into from Jan 29, 2016

Conversation

Projects
None yet
2 participants
@craig65535

craig65535 commented Aug 2, 2013

Setting @reopen_on_eof on a file move notification could result in data not being read from the input file.
Say I want to use FileTail to read a log file. Typically, a log file is rolled/rotated by:

  1. Renaming it (X -> Y)
  2. Closing it (and flushing any output)
  3. Reopening a new file with the original name (X)
    If, between steps 1 and 2, FileTail receives notification the file was moved, sets @reopen_on_eof, reads, and gets an EOF, it will miss any data that was not flushed by the process writing the file.
    However, this case is handled correctly in a different part of the code. If a normal read results in an EOF, @reopen_on_eof will be set if the file exists (by name) and has a changed inode. Therefore, setting @reopen_on_eof here is unnecessary.
Craig Davison
When the input file is moved, do not set @reopen_on_eof right away.
Setting @reopen_on_eof on a file move notification could result in data not being read from the input file.
Say I want to use FileTail to read a log file. Typically, a log file is rolled/rotated by:
1. Renaming it (X -> Y)
2. Closing it (and flusing any output)
3. Reopening a new file with the original name (X)
If, between steps 1 and 2, FileTail receives notification the file was moved, sets @reopen_on_eof, reads, and gets an EOF, it will miss any data that was not flushed by the process writing the file.
However, this case is handled correctly in a different part of the code. If a normal read results in an EOF, @reopen_on_eof will be set if the file exists (by name) and has a changed inode. Therefore, setting @reopen_on_eof here is unnecessary.
@craig65535

This comment has been minimized.

Show comment
Hide comment
@craig65535

craig65535 Aug 14, 2013

@jordansissel Do you have time to review this? It fixes a big in FileTail. Thank you

craig65535 commented Aug 14, 2013

@jordansissel Do you have time to review this? It fixes a big in FileTail. Thank you

@craig65535

This comment has been minimized.

Show comment
Hide comment
@craig65535

craig65535 Sep 4, 2014

@jordansissel revisiting this after a year. Is this project dead?

craig65535 commented Sep 4, 2014

@jordansissel revisiting this after a year. Is this project dead?

@craig65535

This comment has been minimized.

Show comment
Hide comment
@craig65535

craig65535 Sep 4, 2014

If you need it, I have code to reproduce this bug that I can paste into a gist.

craig65535 commented Sep 4, 2014

If you need it, I have code to reproduce this bug that I can paste into a gist.

@craig65535

This comment has been minimized.

Show comment
Hide comment
@craig65535

craig65535 Jan 15, 2016

@jayson Any chance this could get another look, now that we have a maintainer?

craig65535 commented Jan 15, 2016

@jayson Any chance this could get another look, now that we have a maintainer?

@jayson

This comment has been minimized.

Show comment
Hide comment
@jayson

jayson Jan 15, 2016

Collaborator

@craig65535 Sure, can you provide a gist for reproducing it?

Collaborator

jayson commented Jan 15, 2016

@craig65535 Sure, can you provide a gist for reproducing it?

@craig65535

This comment has been minimized.

Show comment
Hide comment
@craig65535

craig65535 Jan 16, 2016

https://gist.github.com/craig65535/bf1071592c0f24379c72

I wrote a C program (writer.c) to write lines to a file. When it receives a SIGUSR1 signal it closes the file, reopens another file with the same name, and keeps writing.

I wrote a ruby script (reader.rb) to tail the file with EventMachine::file_tail and write what it reads to another file.

I wrote a perl script to start both programs and periodically rename the file opened by the writer, and then send SIGUSR1 to the writer. What should happen is that the output file of reader.rb should be all complete, consecutive lines. Instead, some lines are missing and cut off because EventMachine::file_tail is losing input.

Put these 4 files in a directory and run make. Then, run perl tester.pl. It runs writer for 10 seconds, sending the signal every 0.2 seconds.

Before my change:

open /tmp/y
scanning
Line 248: [[000248] We're no strangers to love. You know th[000660] We're no strangers to love. You know the rules and so do I. A full commitment's what I'm thinking of. You wouldn't get this from any other guy.
]
Lines 248 through 660 missing
Line 328: [[000740] We're no strangers to love. You know th[001167] We're no strangers to love. You know the rules and so do I. A full commitment's what I'm thinking of. You wouldn't get this from any other guy.
]
Lines 740 through 1167 missing
close

After my change:

open /tmp/y
scanning
close

You might need to run it more than once to see this happen.

This was a bug that plagued my team for some months before I tracked it down to this gem.

craig65535 commented Jan 16, 2016

https://gist.github.com/craig65535/bf1071592c0f24379c72

I wrote a C program (writer.c) to write lines to a file. When it receives a SIGUSR1 signal it closes the file, reopens another file with the same name, and keeps writing.

I wrote a ruby script (reader.rb) to tail the file with EventMachine::file_tail and write what it reads to another file.

I wrote a perl script to start both programs and periodically rename the file opened by the writer, and then send SIGUSR1 to the writer. What should happen is that the output file of reader.rb should be all complete, consecutive lines. Instead, some lines are missing and cut off because EventMachine::file_tail is losing input.

Put these 4 files in a directory and run make. Then, run perl tester.pl. It runs writer for 10 seconds, sending the signal every 0.2 seconds.

Before my change:

open /tmp/y
scanning
Line 248: [[000248] We're no strangers to love. You know th[000660] We're no strangers to love. You know the rules and so do I. A full commitment's what I'm thinking of. You wouldn't get this from any other guy.
]
Lines 248 through 660 missing
Line 328: [[000740] We're no strangers to love. You know th[001167] We're no strangers to love. You know the rules and so do I. A full commitment's what I'm thinking of. You wouldn't get this from any other guy.
]
Lines 740 through 1167 missing
close

After my change:

open /tmp/y
scanning
close

You might need to run it more than once to see this happen.

This was a bug that plagued my team for some months before I tracked it down to this gem.

@jayson

This comment has been minimized.

Show comment
Hide comment
@jayson

jayson Jan 19, 2016

Collaborator

@craig65535 Thanks for the detailed gist! I'll take a look into this in the next few days and if it looks good merge it in

Collaborator

jayson commented Jan 19, 2016

@craig65535 Thanks for the detailed gist! I'll take a look into this in the next few days and if it looks good merge it in

@craig65535

This comment has been minimized.

Show comment
Hide comment
@craig65535

craig65535 Jan 19, 2016

Just to explain this a little more on a macro level, I wanted the proof of concept to be somewhat realistic (although it rotates logs much faster than a typical setup). writer acts like a daemon that writes to a log and responds to a signal to rotate the log. tester.pl acts like logrotate in that it renames the log and sends a signal. reader.rb is tailing the log.

craig65535 commented Jan 19, 2016

Just to explain this a little more on a macro level, I wanted the proof of concept to be somewhat realistic (although it rotates logs much faster than a typical setup). writer acts like a daemon that writes to a log and responds to a signal to rotate the log. tester.pl acts like logrotate in that it renames the log and sends a signal. reader.rb is tailing the log.

jayson added a commit that referenced this pull request Jan 29, 2016

Merge pull request #23 from craig65535/fix-immediate-reopen-on-file-m…
…oved

When the input file is moved, do not set @reopen_on_eof right away.

@jayson jayson merged commit ef31cb9 into jordansissel:master Jan 29, 2016

@jayson

This comment has been minimized.

Show comment
Hide comment
@jayson

jayson Jan 29, 2016

Collaborator

Looks good to me, merged

Collaborator

jayson commented Jan 29, 2016

Looks good to me, merged

@craig65535

This comment has been minimized.

Show comment
Hide comment
@craig65535

craig65535 Jan 29, 2016

Great! TYVM

craig65535 commented Jan 29, 2016

Great! TYVM

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment