Hi Community!
I have a strange behaviour with monitoring a configuration file.
Since a specific time we get duplicate events from this file.
I see in splunkd.log that every 3 seconds this file was read again.
11-21-2016 13:34:01.630 +0100 INFO WatchedFile - Will begin reading at offset=0 for file='/opt/mainapp/ap.conf'.
11-21-2016 13:34:01.632 +0100 INFO WatchedFile - Will begin reading at offset=0 for file='/opt/mainapp/ap.conf'.
11-21-2016 13:34:04.500 +0100 INFO WatchedFile - Will begin reading at offset=0 for file='/opt/mainapp/ap.conf'.
11-21-2016 13:34:04.501 +0100 INFO WatchedFile - Will begin reading at offset=0 for file='/opt/mainapp/ap.conf'.
11-21-2016 13:34:07.502 +0100 INFO WatchedFile - Will begin reading at offset=0 for file='/opt/mainapp/ap.conf'.
11-21-2016 13:34:07.504 +0100 INFO WatchedFile - Will begin reading at offset=0 for file='/opt/mainapp/ap.conf'.
11-21-2016 13:34:10.504 +0100 INFO WatchedFile - Will begin reading at offset=0 for file='/opt/mainapp/ap.conf'.
and in metrics.log I see that data and events for this file was send to the indexer,
but the file itself, wasn't updated. or any changes wasn't made.
11-21-2016 13:33:47.812 +0100 INFO Metrics - group=per_source_thruput, series="/opt/mainapp/ap.conf", kbps=4.090971, eps=0.967770, kb=126.816406, ev=30, avg_age=2836.166667, max_age=8522
11-21-2016 13:34:18.813 +0100 INFO Metrics - group=per_source_thruput, series="/opt/mainapp/ap.conf", kbps=4.090742, eps=0.967716, kb=126.816406, ev=30, avg_age=2846.166667, max_age=8552
11-21-2016 13:34:49.813 +0100 INFO Metrics - group=per_source_thruput, series="/opt/mainapp/ap.conf", kbps=4.499917, eps=1.064511, kb=139.498047, ev=33, avg_age=2856.666667, max_age=8585
11-21-2016 13:35:20.813 +0100 INFO Metrics - group=per_source_thruput, series="/opt/mainapp/ap.conf", kbps=4.090934, eps=0.967761, kb=126.816406, ev=30, avg_age=2867.166667, max_age=8615
It is interessting because the duplicate events occurs all on the last change timestamp
This is the Inputs.conf
[monitor:///opt/mainapp/ap.conf]
disabled = false
followTail = false
index = app
sourcetype = app_conf
ignoreOlderThan = 1h
Do you have an idea what's going wrong, because this file monitor works since a few years.
Another thing is, that since a few weeks the UF was upgraded to 6.5.0, maybe this has an influence to this behaviour?
Thanks
Robert
The only thing I see that might cause that is the followTail, because as you recall:
If set to 0, monitoring starts at the beginning of the file.
Because this was a Default Logfile Setting for our Logfiles.
In this case it is disabled, because it is not a Logfile but a Config File.
The Config File has ~13kB size.
Why do we need followTail = false
?
What I have now seen with category.WatchedFile=DEBUG is, that splunk thinks that initcrc has changed and so it reads the file again.
11-21-2016 14:53:48.225 +0100 DEBUG WatchedFile - Reading for plain initCrc...
11-21-2016 14:53:48.226 +0100 DEBUG WatchedFile - Preserving seekptr and initcrc.
11-21-2016 14:53:49.227 +0100 DEBUG WatchedFile - Loading state from fishbucket.
11-21-2016 14:53:49.227 +0100 DEBUG WatchedFile - /opt/mainapp/ap.conf requested modtime-based check.
11-21-2016 14:53:49.227 +0100 DEBUG WatchedFile - initcrc has changed to: 0x94f5d6b84fc81987.
11-21-2016 14:53:49.227 +0100 DEBUG WatchedFile - Comparing current & stored modtime.
11-21-2016 14:53:49.227 +0100 INFO WatchedFile - Will begin reading at offset=0 for file='/opt/mainapp/ap.conf'.
11-21-2016 14:53:49.227 +0100 DEBUG WatchedFile - Preserving seekptr and initcrc.
11-21-2016 14:53:49.227 +0100 DEBUG WatchedFile - seeking /opt/mainapp/ap.conf to off=12986
11-21-2016 14:53:49.227 +0100 DEBUG WatchedFile - Reached EOF: fname=/opt/mainapp/ap.conf fishstate=key=0xc4816c5e3dd5e78a sptr=12986 scrc=0x0 fnamecrc=0x94f5d6b84fc81987 modtime=1479723104
11-21-2016 14:53:49.228 +0100 DEBUG WatchedFile - Storing pending metadata for file=/opt/mainapp/ap.conf, sourcetype=app_conf, charset=UTF-8
11-21-2016 14:53:49.228 +0100 DEBUG WatchedFile - setting trailing nulls to false via 'true' or 'false' from conf'
11-21-2016 14:53:49.228 +0100 DEBUG WatchedFile - Creating new pipeline input channel with channel id: 105.
11-21-2016 14:53:49.228 +0100 DEBUG WatchedFile - Attempting to load indexed extractions config from conf=source::/opt/mainapp/ap.conf|host::mainapp.local|app_conf|105 ...
11-21-2016 14:53:49.229 +0100 DEBUG WatchedFile - Loading state from fishbucket.
11-21-2016 14:53:49.229 +0100 DEBUG WatchedFile - /opt/mainapp/ap.conf requested modtime-based check.
11-21-2016 14:53:49.229 +0100 DEBUG WatchedFile - initcrc has changed to: 0x94f5d6b84fc81987.
11-21-2016 14:53:49.229 +0100 DEBUG WatchedFile - Comparing current & stored modtime.
11-21-2016 14:53:49.229 +0100 INFO WatchedFile - Will begin reading at offset=0 for file='/opt/mainapp/ap.conf'.
11-21-2016 14:53:49.229 +0100 DEBUG WatchedFile - seeking /opt/mainapp/ap.conf to off=0
11-21-2016 14:53:49.229 +0100 DEBUG WatchedFile - Reading for plain initCrc...
11-21-2016 14:53:49.229 +0100 DEBUG WatchedFile - initcrc changed to 0xc4816c5e3dd5e78a since file grew past initCrcLen.
11-21-2016 14:53:49.229 +0100 DEBUG WatchedFile - Applying pending meta data
11-21-2016 14:53:49.229 +0100 DEBUG WatchedFile - Clearing pending metadata
11-21-2016 14:53:49.229 +0100 DEBUG WatchedFile - Reached EOF: fname=/opt/mainapp/ap.conf fishstate=key=0xc4816c5e3dd5e78a sptr=12986 scrc=0x0 fnamecrc=0x94f5d6b84fc81987 modtime=1479723104
I am also now seeing this behavior after upgrading our forwarders to 6.5.0. I noticed in the splunkd.log that watchedfile appears to be digging deeper into our directory. We do have recursive enabled but I don't have an input at all for followTail = false/true. This was not an issue before but we are now seeing some delay in ingestion during the times that watchedfile is kicking off.