Duplicate events at the same time

[RobertRi]

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

[TiagoTLD1]

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.

[RobertRi]

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.

[ddrillic]

Why do we need followTail = false?

[RobertRi]

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

[sbrice36]

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.