Repository navigation
Fluentd in_tail "unreadable" file causes "following tail of <file>" to stop and no logs pushed #3614
Copy link
Copy link
Description
Describe the bug
After a warning of an "unreadable" (likely due to rotation), no more logs were pushed (in_tail + pos_file).
Reloading config or restarting fluentd sorts the issue.
All other existing files being tracked continued to work as expected.
To Reproduce
Not able to reproduce at will.
Expected behavior
Logs to be pushed as usual after file rotation as fluentd recovers from the temporary "unreadable" file.
Your Environment
- Fluentd version: 1.14.4
- TD Agent version: 4.2.0
- Operating system: Ubuntu 20.04.3 LTS
- Kernel version: 5.11.0-1022-awsYour Configuration
<source>
@type tail
path /var/log/containers/*.log
pos_file /var/log/es-containers.log.pos
tag kubernetes.*
<parse>
@type regexp
expression /^(?<time>[^ ]+) (?<stream>[^ ]+) (?<logtag>[^ ]+) (?<log>.+)$/
time_key time
time_format %Y-%m-%dT%H:%M:%S.%N%z
</parse>
read_from_head true
</source>Your Error Log
Relevant log entries with some context. When "detected rotation of ..." isn't followed by a "following tail of ..." then log file contents aren't being processed/pushed:
2022-02-01 01:26:33 +0000 [info]: #0 detected rotation of /var/log/containers/gateway-mtcw6_atom_pcms-gateway-e54ea9ee115f1127682b0d92e37404e4b1693c14edeea93e485f70b3110eecfc.log; waiting 5 seconds
2022-02-01 01:26:33 +0000 [info]: #0 following tail of /var/log/containers/gateway-mtcw6_atom_pcms-gateway-e54ea9ee115f1127682b0d92e37404e4b1693c14edeea93e485f70b3110eecfc.log
2022-02-01 01:32:53 +0000 [warn]: #0 /var/log/containers/gateway-mtcw6_atom_pcms-gateway-e54ea9ee115f1127682b0d92e37404e4b1693c14edeea93e485f70b3110eecfc.log unreadable. It is excluded and would be examined next time.
2022-02-01 01:32:54 +0000 [info]: #0 detected rotation of /var/log/containers/gateway-mtcw6_atom_pcms-gateway-e54ea9ee115f1127682b0d92e37404e4b1693c14edeea93e485f70b3110eecfc.log; waiting 5 seconds
2022-02-01 01:32:54 +0000 [info]: #0 following tail of /var/log/containers/gateway-mtcw6_atom_pcms-gateway-e54ea9ee115f1127682b0d92e37404e4b1693c14edeea93e485f70b3110eecfc.log
2022-02-01 01:38:04 +0000 [info]: #0 detected rotation of /var/log/containers/gateway-mtcw6_atom_pcms-gateway-e54ea9ee115f1127682b0d92e37404e4b1693c14edeea93e485f70b3110eecfc.log; waiting 5 seconds
2022-02-01 01:44:44 +0000 [info]: #0 detected rotation of /var/log/containers/gateway-mtcw6_atom_pcms-gateway-e54ea9ee115f1127682b0d92e37404e4b1693c14edeea93e485f70b3110eecfc.log; waiting 5 seconds
2022-02-01 01:53:15 +0000 [info]: #0 detected rotation of /var/log/containers/gateway-mtcw6_atom_pcms-gateway-e54ea9ee115f1127682b0d92e37404e4b1693c14edeea93e485f70b3110eecfc.log; waiting 5 seconds
[...]
---- after issuing a config reload (kill -SIGUSR2 <pid>) it starts to work fine again, i.e. "following tail of ..."
2022-02-01 11:36:19 +0000 [info]: Reloading new config
2022-02-01 11:36:19 +0000 [info]: using configuration file: <ROOT>
[...]
2022-02-01 11:36:19 +0000 [info]: shutting down input plugin type=:tail plugin_id="object:c6c0"
[...]
2022-02-01 11:36:19 +0000 [info]: adding source type="tail"
2022-02-01 11:36:19 +0000 [info]: #0 shutting down fluentd worker worker=0
2022-02-01 11:36:19 +0000 [info]: #0 shutting down input plugin type=:tail plugin_id="object:c6c0"
[...]
2022-02-01 11:36:20 +0000 [info]: #0 restart fluentd worker worker=0
---- the entry below seems to be related with the actual underlying issue... the ruby object which stopped pushing logs has now been terminated as a new one was created
2022-02-01 11:36:20 +0000 [warn]: #0 /var/log/containers/gateway-mtcw6_atom_pcms-gateway-e54ea9ee115f1127682b0d92e37404e4b1693c14edeea93e485f70b3110eecfc.log already exists. use latest one: deleted #<struct Fluent::Plugin::TailInput::Entry path="/var/log/containers/gateway-mtcw6_atom_pcms-gateway-e54ea9ee115f1127682b0d92e37404e4b1693c14edeea93e485f70b3110eecfc.log", pos=10740032, ino=1797715, seek=1530>
2022-02-01 11:36:20 +0000 [info]: #0 following tail of /var/log/containers/gateway-mtcw6_atom_pcms-gateway-e54ea9ee115f1127682b0d92e37404e4b1693c14edeea93e485f70b3110eecfc.log
2022-02-01 11:37:30 +0000 [info]: #0 detected rotation of /var/log/containers/gateway-mtcw6_atom_pcms-gateway-e54ea9ee115f1127682b0d92e37404e4b1693c14edeea93e485f70b3110eecfc.log; waiting 5 seconds
2022-02-01 11:37:30 +0000 [info]: #0 following tail of /var/log/containers/gateway-mtcw6_atom_pcms-gateway-e54ea9ee115f1127682b0d92e37404e4b1693c14edeea93e485f70b3110eecfc.log
2022-02-01 11:43:20 +0000 [info]: #0 detected rotation of /var/log/containers/gateway-mtcw6_atom_pcms-gateway-e54ea9ee115f1127682b0d92e37404e4b1693c14edeea93e485f70b3110eecfc.log; waiting 5 seconds
2022-02-01 11:43:20 +0000 [info]: #0 following tail of /var/log/containers/gateway-mtcw6_atom_pcms-gateway-e54ea9ee115f1127682b0d92e37404e4b1693c14edeea93e485f70b3110eecfc.logAdditional context
This issue seems be related with #3586 but unfortunately I didn't check the pos file while the issue was happening so can't tell if it presented unexpected values for the failing file.
Reactions are currently unavailable
Metadata
Metadata
Labels
bugSomething isn't workingSomething isn't working
Type
Projects
- StatusShow more project fieldsDone
Activity
mizunashi-mana commentedon Feb 14, 2022
We have encountered the same problem twice. Last month we upgraded fluentd from 1.13.3 (td-agent 4.2.0) to 1.14.3 (td-agent 4.3.0), and then we have got the problem.
In our case, we are tracking more than 3 log files with the tail plugin, and only the file with the highest log flow has this problem. From the metrics produced by prometheus plugin, the file position always fluctuates by at least 400000/sec and the rotation happens at least once every 10 minutes.
The input source is set as follows:
I will also share the record of the investigation when the problem occurs. First, fluentd suddenly, without warning, stops tracking new rotated files and only logs the following in the stdout log.
Normally, it would have been followed by an announcement that a new file was being tracked, as follows
However, we have not seen this announcement at all after the problem occurs. Also, when I view the file descriptors that fluentd is tracking, I see the following:
This is the rotated file, and we see that fluentd is still tracking the old file, not the new one. Also, looking at the position file, we see the following:
As far as the situation is concerned, it seems that something triggers fluentd to stop tracking new files altogether during rotate. We have about 300 servers running 24/7 and have only had two problems in the past month, so it seems to be pretty rare for problems to occur. However, since we haven't had any problems with fluentd 1.13.3 for 6 months, it seems likely that there was some kind of regression in fluentd 1.13.3 -> 1.14.3.
We are planning to downgrade fluentd.
ashie commentedon Feb 14, 2022
Memo: From v1.14.0 to v1.14.3, following changes are made to in_tail:
mizunashi-mana commentedon Feb 22, 2022
We downgraded td-agent 4.3.0 (fluentd v1.14.3) to td-agent 4.2.0 (fluentd v1.13.3), and still have problems.
We broadened monitoring targets to 500 servers (approx 1500 files) from 200 servers (approx 400 files) as a result of this issue. Then, we found the 2 servers (2 files) having this issue after a week from td-agent downgraded.
Upgrading fluentd 1.13.3 -> 1.14.3 does not seem to be the cause, sorry.
It seemed that some of our log files were affected and some were not. The differences are as follows.
We are planning to change rotation policy and retry upgrading td-agent. And, we will comment some updates if we get.
mizunashi-mana commentedon Mar 17, 2022
We enabled debug logging with fluentd 1.13.3 and encountered this issue. The state was same:
detected rotation of /var/log/server.log; waiting 5 secondswithoutThe following tail of /var/log/server.log./var/log/server.log 0000000000000000 0000000000000000.fluentd_tail_file_inodemetrics had been keeping the same inode from this issue occurred.And, fluentd reported
Skip update_watcher because watcher has been already updated by other inotify eventfollowingdetected rotation of /var/log/server.log; waiting 5 seconds. The message seems to be reported by https://github.com/fluent/fluentd/blob/v1.13.3/lib/fluent/plugin/in_tail.rb#L482. It seems to be strongly related position file having two entries.We searched some other debug logs related this issue but we had no such logs. fluentd reported no other debug logs but only pairs of
detected rotation of /var/log/server.log; waiting 5 secondsandThe following tail of /var/log/server.log.ashie commentedon Mar 17, 2022
Thanks for your report!
To tell the truth, I was suspecting it but I couldn't confirm it because I can't yet reproduce it.
Your report it very helpful for me.
Although I'm not yet sure the mechanism of this issue, you might be able to avoid this issue by disabling stat watcher (
enable_stat_watcher false).ashie commentedon Jul 8, 2022
Similar reports:
pos_file_compaction_interval 3menable_stat_watcher falseashie commentedon Jul 8, 2022
From #3586
ashie commentedon Jul 8, 2022
There are several similar reports and most of them said:
When tailing is stopped,
was observed but
wasn't observed.
In addition, a user reports that following debug message is observed when log level is debug:
So, it seems caused by the following code:
fluentd/lib/fluent/plugin/in_tail.rb
Lines 489 to 498 in 438a82a
salavessa commentedon Jul 8, 2022
For what's worth: after adding
enable_stat_watcher falseback in March (as mentioned by @ashie here) none of my 120+ servers experienced this issue again.xhwdt commentedon Jul 15, 2022
@ashie Is this one fixed?
in_tail: Show more information on skipping update_watcher
81 remaining items
uristernik commentedon Dec 28, 2023
We are still seeing this issue as well. We are using this image v1.16.3-debian-forward-1.0.
We were seeing the following message
If you keep getting this message, please restart Fluentdand like suggested here we changedfollow_inodestotrueand setrotate_waitto0, but we are still seeing loads ofSkip update_watcher because watcher has been already updated by other inotify eventWe also noticed a pattern of memory leaking and gradual increase in CPU usage until a restart occurs. We are using fluentd as a daemonset on a kubernetes cluster. Here is our
in_tailconfig:uristernik commentedon Jan 1, 2024
In an environment where we have high volatility (we constantly deploy new code -> deployments are restarted very frequently -> pods are created -> lots of files to tail) we see a clear leak pattern.
Like mentioned above this is coupled with a huge amount of:
Any suggestion to mitigate this? @ashie @daipom
Maybe setting
pos_file_compaction_intervalto some value so we would stop watching rotated files? (of pods that no longer exist)alexei-g-aloteq commentedon Jan 3, 2024
BTW, any good alternatives for Fluentd?
It does not seem to be reliable at the moment.
This issue kept unfixed for years.
zmedico commentedon Jan 3, 2024
I've observed this issue with v1.16.3. I suspect that in_tail handling of file rotations is unlikely to ever reach a satisfactory level of reliability, and something like the docker fluentd logging driver (which unfortunately breaks
kubectl logs) is the only way to reliably avoid problems with log file rotation.I suspect that my
open_on_every_update trueconfig might be making problems worse (not to mention that it introduces a race to collect log entries during log rotation), so I'm going to try disabling that to see if it helps.zmedico commentedon Jan 4, 2024
Setting
open_on_every_update falsedid not seem to help for me. Interestingly, the issue did not appear to correlate with a log rotation, since the log file that it was not following was still older than the fluentd process. Fluentd was following the file through two levels of symlinks, and the symlink timestamps are older than the actual log file, so I don't know how to explain why it triggered the "unreadable" log message.daipom commentedon Jan 5, 2024
Thanks for reporting.
So, there are still problems with both
follow_inodes falseandfollow_inodes true, such as collection stops and resource leaks.ashie commentedon Jan 5, 2024
#4326 would be a possible remaining cause of this issue.
On the other hand it might not be related with above additional reports because #4326 says no error log is found.
ashie commentedon Jan 5, 2024
BTW it would be better to open a new issue to treat remaining things.
This issue is too long and mixed various causes.
It seems hard to collect & track informations to debug remaining causes in this issue.
uristernik commentedon Jan 7, 2024
@ashie @daipom Thanks for the responses and attention.
Should I open a new issue for that?
If you have any suggestion I'll be more than happy to test different configs.
I added the
pos_file_compaction_interval 20mto the config but still seeing that Fluentd is leaking CPUdaipom commentedon Jan 9, 2024
@uristernik Thanks. Could you please open a new issue?
uristernik commentedon Jan 15, 2024
@daipom Done, hopefully I described the issue clear enough. Please correct me if I wasn't accurate enough
daipom commentedon Jan 16, 2024
@uristernik Thanks! I will check it!
daipom commentedon Jan 16, 2024
If you all still have a similar issue, please report it on the new issue!