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

in_tail: Handle records in the correct order on file rotation #1880

Merged

Conversation

fujimotos
Copy link
Member

This is the fix for the issue reported by the bug report #1055.

Problem

It turned out that this bug was a matter of the calling order of functions in TailWatcher.on_rotate().

In particular, when TailWatcher detects a log rotation and immediately finds a new file, it performs the following steps:

  1. Create a new TailWatcher for the new file.
    • In this process, it reads the new file and emit its contents.
    • This all happens before proceeding to (2).
  2. Dispatch the on_notify() for the archived file.
    • In this process, it reads the content of the old file and emit its contents.

So naturally, newer log records (written to the new log file) will be emitted before older records in the archived log file.

Solution

This patch fixes it by enforcing flush of older log records before performing the step (1).

@fujimotos
Copy link
Member Author

fujimotos commented Mar 6, 2018

Why doesn't this bug occur on every rotation?

Note that this bug occurs only when TailInput is slow to notice the file rotation.

In most cases, it does not occur because a log rotation is detected immediately after
the file rename (= before the new log file is created). In such a case, a file rotation
will be handled as follows.

  1. Detect the rename of the log file and set up a new TailWatcher.
    • In this step, the new file is NOT created yet, so nothing is emitted.
  2. Dispatch the on_notify() for the archived log file.
  3. Detect the creation of the new log file.
    • In this step, the content of the new file gets processed.

As you can see, TailInpout handles the content of the old file in the step 2 and the
content of the new file in the step 3, so the output order of records is preserved.

This is a fix for the events-emitted-in-the-wrong-order bug reported by
fluentd#1055. It turned out that this bug was a matter of the calling
order of functions in TailWatcher.on_rotate().

In particular, when TailWatcher detects a log rotation and immediately
finds a new file, it performs the following steps:

  1) Create a new TailWatcher for the new file.
    * In this process, it reads the new file and emit its contents.
    * All of this happens before proceeding to (2).
  2) Read the old file and emit its contents.

So naturally, newer log records (written to the new log file) will be
emitted before older records in the archived log file.

This patch fixes it by enforcing flush of older log records before
performing the step (1).
@fujimotos fujimotos force-pushed the sf/fix-reversed-order-events-on-rotate branch from da990f9 to 9578a51 Compare March 6, 2018 06:01
@repeatedly repeatedly merged commit 0fefbfb into fluent:master Mar 10, 2018
@repeatedly
Copy link
Member

Thanks for the investigation and patch. Just merged :)

@fujimotos
Copy link
Member Author

Thanks for merging it!

@fujimotos fujimotos deleted the sf/fix-reversed-order-events-on-rotate branch March 12, 2018 01:19
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 this pull request may close these issues.

2 participants