Fluentd-kubernetes-daemonset: Fluentd misses log file when >1 app log rotation happens back to back

[pranavmarla]

Summary
When an application container generates a burst of logs, such that > 1 log rotation happens back to back within a few seconds, then the Fluentd daemonset doesn't seem to detect all the log rotations (i.e. only detects SOME of the log rotations) and, thus, completely misses the intermediate/middle log files.

Eg. If the app has generated a big enough burst of logs to trigger 2 log rotations back to back within a few seconds, that means there are now 3 app container log files:

1. app.log.2 (oldest)
   |
   |
   1st log rotation
   |
   v
2. app.log.1
   |
   |
   2nd log rotation
   |
   v
3. app.log (newest)

In this scenario, Fluentd thinks only 1 log rotation has happened, and only captures logs written to the first/oldest and third/newest log files -- the entire middle file is missed!

Details
I am running the Fluentd daemonset on a Kubernetes cluster. As is recommended for any Kubernetes cluster, to collect the container logs, Fluentd is configured to tail /var/log/containers.

As is standard with Kubernetes clusters, /var/log/containers consists of symlinks pointing to the actual Docker container log files in /var/lib/docker/containers.
i.e. The file structure looks like this:

/var/log/containers                     /var/lib/docker/containers
-------------------                     --------------------------
    app-symlink.log -----------------------------> app.log

My cluster is configured to rotate the container log files (in /var/lib/docker/containers) when any of them reaches 100 MB.
For my testing, I used a sample app container that can generate a burst of logs on demand -- for my cluster, having the app generate 500,000 logs was enough to trigger 2 log rotations back to back, creating a total of 3 container log files in /var/lib/docker/containers.
i.e. The file structure looked like this:

Before any log rotation:

/var/log/containers                     /var/lib/docker/containers
-------------------                     --------------------------
    app-symlink.log -----------------------------> app.log


#############


After 1st log rotation:

/var/log/containers                     /var/lib/docker/containers
-------------------                     --------------------------
    app-symlink.log -----------------------------> app.log (newer)
                                                   app.log.1 (older, full)


#############


After 2nd log rotation:

/var/log/containers                     /var/lib/docker/containers
-------------------                     --------------------------
    app-symlink.log -----------------------------> app.log (newest)
                                                   app.log.1 (older, full)
                                                   app.log.2 (oldest, full)

To show how quickly these log rotations are happening, here are some example timestamps from my testing:
(Note that timestamps in Unix are not the creation time of the file -- instead, they are the last modified time)

2020-07-16 18:26:17.602009787 app.log
2020-07-16 18:26:11.865931348 app.log.1
2020-07-16 18:26:04.553831355 app.log.2

So, at this point, 2 log rotations have happened, creating 3 log files -- however, if we look at Fluentd's internal logs, we see that it has detected only 1 log rotation!
Specifically, based on the timestamps, it appears to have missed the 1st log rotation and only detected the 2nd one.

2020-07-16 18:11:32.744 following tail of /var/log/containers/app-symlink.log
...
2020-07-16 18:26:16.707 detected rotation of /var/log/containers/app-symlink.log; waiting 5 seconds
2020-07-16 18:26:16.707 following tail of /var/log/containers/app-symlink.log

Since Fluentd has only detected 1 log rotation, it wrongly thinks that only 2 log files have been created -- specifically, it only captures logs from the 1st (oldest) and 3rd (newest) log files, completely missing the 2nd log file (_app.log.1_)!

Attempted Fixes

_1. rotate_wait:_

Initially, it seemed obvious what was wrong, and how to fix it: As far as I understand, by default, when Fluentd's tail plugin detects a log rotation, it does not immediately start tailing the new log file -- instead, it keeps tailing the old log file for 5 seconds to catch any last logs being flushed to that old log file, before moving to the new log file.

My theory was that, in my example with 3 log files, when Fluentd detects the first log rotation (from 1st to 2nd log file), it keeps tailing that 1st log file for 5 seconds -- unbeknownst to it, in that 5 second period when Fluentd is temporarily 'blind', another log rotation has happened (from 2nd to 3rd log file), which Fluentd does not know about. Thus, after 5 seconds, Fluentd THINKS it is moving to the 2nd log file, but it is actually moving to the 3rd log file, and has completely missed the real 2nd log file.

The 5s delay is controlled by the rotate_wait tail plugin param. Given my theory, I assumed that the 'fix' would be as simple as reducing _rotate_wait_ -- thus, Fluentd would be blind for a shorter amount of time, and would move on to the real 2nd log file before the 2nd log rotation happens.
Unfortunately, when I tried reducing _rotate_wait_ to 1s (and even 0s), it had no effect -- Fluentd still only detected 1 log rotation, and still only tailed the 1st and 3rd log files.
Also, if we examine the timestamps of Fluentd's internal logs, it seems more likely that, contrary to my theory above, Fluentd is actually missing the 1st log rotation, and only detecting the 2nd/final one.

_2. refresh_interval:_

I then tried reducing the refresh_interval tail plugin param from its default value of 60s. Unfortunately, reducing _refresh_interval_ to 1s (and even 0s) had no effect either.

_3. rotate_wait and refresh_interval:_
Finally, I tried various combinations of _rotate_wait_ and _refresh_interval_, but none of them had any effect.
Eg.

rotate_wait: 5s    refresh_interval: 1s
rotate_wait: 1s    refresh_interval: 1s
rotate_wait: 0s    refresh_interval: 1s
rotate_wait: 0s    refresh_interval: 0s

Mitigation
At this point, I am out of ideas on how to fix this in Fluentd.

When I searched online, I could find only one other person with the same issue as me: link
In that article, they don't have a Fluentd fix either -- instead, they seem to have increased the log file size that triggers log rotation to make it harder to trigger 2 log rotations in a row, as a workaround on the cluster side.

For now, I am planning to do the cluster workaround as a short-term mitigation, but I would much prefer an actual fix that I can apply on the Fluentd side. Please let me know if you have any ideas, or need more information from me!

Config Details

Kubernetes cluster log rotation settings: Container log file rotates when it reaches 100 MB, total of 3 log files retained.

Fluentd Docker image version: v1.10.4-debian-forward-1.0

Fluentd tail config:

<source>
  @type tail

  tag kubernetes.*

  path /var/log/containers/*.log
  exclude_path [
    "/var/log/containers/fluentd-agent-*.log",
    ...
    ]

  pos_file /var/log/container.log.pos

  <parse>
    @type "#{ENV['FLUENT_CONTAINER_TAIL_PARSER_TYPE'] || 'json'}"
    time_format %Y-%m-%dT%H:%M:%S.%NZ
  </parse>

  path_key log_file
  read_from_head true
  pos_file_compaction_interval 24h

  # Default settings
  rotate_wait 5s
  refresh_interval 60s

  # The inotify-based file watcher (i.e. stat_watcher) does not seem to work -- thus, we disable stat_watcher and enable watch_timer instead.
  enable_watch_timer true
  enable_stat_watcher false
</source>

[takryo00]

@pranavmarla
https://github.com/fluent/fluentd-kubernetes-daemonset/issues/366#issuecomment-720019764

[github-actions[bot]]

This issue has been automatically marked as stale because it has been open 90 days with no activity. Remove stale label or comment or this issue will be closed in 30 days

[pranavmarla]

@takryo00 Thanks for linking to #366! I'm afraid I must have missed it at the time.

However, if I understand this comment from #366, the suggestion is that, because Fluentd on Kubernetes is tailing the symlinks rather than the actual log files themselves, Fluentd cannot detect any rotations in the log files.

However, to clarify, that is not the behaviour I see here: In my testing, Fluentd DOES usually detect the log rotation properly, even though it's tailing the symlinks. The issue here only arises when there are MULTIPLE log rotations happening one after the other very quickly -- in that case, Fluentd only catches SOME of the log rotations (whereas we expect it to catch ALL of the log rotations).

[github-actions[bot]]

This issue has been automatically marked as stale because it has been open 90 days with no activity. Remove stale label or comment or this issue will be closed in 30 days

[pranavmarla]

Bump

[cosmo0920]

Fluentd's tailing file plugin which is in_tail is keeping reference for rotated file in 5 seconds by default:
https://github.com/fluent/fluentd/blob/master/lib/fluent/plugin/in_tail.rb#L71

This parameter is used as-is in this daemonset.
Do you know or measure how frequent to be log rotated your container files?

[pranavmarla]

Hi @cosmo0920, thanks for checking this out! Regarding your question:

1. I don't know how frequently my container log files get rotated. To be clear though, what I described here is not an issue I run into on a daily basis. This is an edge case -- _if_ my app container generates a burst of logs that is big enough to trigger 2 log rotations back to back, then Fluentd misses one of those log rotations.
2. As mentioned in my original post, I already experimented with reducing the rotate_wait param to 1s (and even 0s), but it made no difference. Similarly with the refresh_interval param.
3. Also, as mentioned in my original post, if the issue was with the 5s rotate_wait param, I would expect Fluentd to miss the _second_ log rotation (since it happens during those 5 seconds when it's still tailing the first, rotated log file). But, if we look at the timestamps of Fluentd's internal logs, it looks like Fluentd is actually missing the _first_ log rotation.