I am having an issue with Splunk reindexing eStreamer log files OVER AND OVER.
12-19-2016 18:21:36.277 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189486'.
12-19-2016 18:21:36.279 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189486'.
12-19-2016 18:21:36.280 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189284'.
12-19-2016 18:21:36.282 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189284'.
12-19-2016 18:21:36.282 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482188776'.
12-19-2016 18:21:36.284 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482188776'.
12-19-2016 18:21:36.285 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482187531'.
12-19-2016 18:21:36.287 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482187531'.
12-19-2016 18:21:37.803 -0500 INFO WatchedFile - Modtime is newer than stored, will reread file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189684'.
12-19-2016 18:21:37.803 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189684'.
12-19-2016 18:21:37.805 -0500 INFO WatchedFile - Modtime is newer than stored, will reread file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189684'.
12-19-2016 18:21:37.805 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189684'.
12-19-2016 18:21:39.281 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189486'.
12-19-2016 18:21:39.283 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189486'.
12-19-2016 18:21:39.284 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189284'.
12-19-2016 18:21:39.285 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189284'.
12-19-2016 18:21:39.286 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482188776'.
12-19-2016 18:21:39.288 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482188776'.
12-19-2016 18:21:39.288 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482187531'.
12-19-2016 18:21:39.290 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482187531'.
12-19-2016 18:21:40.806 -0500 INFO WatchedFile - Modtime is newer than stored, will reread file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189684'.
12-19-2016 18:21:40.807 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189684'.
12-19-2016 18:21:40.808 -0500 INFO WatchedFile - Modtime is newer than stored, will reread file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189684'.
12-19-2016 18:21:40.809 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189684'.
12-19-2016 18:21:42.283 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189486'.
12-19-2016 18:21:42.285 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189486'.
12-19-2016 18:21:42.286 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189284'.
12-19-2016 18:21:42.288 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189284'.
12-19-2016 18:21:42.288 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482188776'.
12-19-2016 18:21:42.291 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482188776'.
12-19-2016 18:21:42.291 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482187531'.
12-19-2016 18:21:42.294 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482187531'.
12-19-2016 18:21:43.810 -0500 INFO WatchedFile - Modtime is newer than stored, will reread file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189684'.
12-19-2016 18:21:43.810 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189684'.
12-19-2016 18:21:43.812 -0500 INFO WatchedFile - Modtime is newer than stored, will reread file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189684'.
12-19-2016 18:21:43.812 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189684'.
12-19-2016 18:21:45.286 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189486'.
12-19-2016 18:21:45.289 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189486'.
Has anyone ever run into this? My inputs.conf is unedited from the Cisco eStreamer for Splunk app.
# cat default/inputs.conf
# Unix/Linux inputs enabled by default
[script://./bin/client_check.py]
disabled = 0
source = eStreamer
sourcetype = client_check
index = estreamer
interval = 60
[monitor://$SPLUNK_HOME/etc/apps/eStreamer/log]
disabled = 0
source = eStreamer
sourcetype = eStreamer
index = estreamer
crcSalt = <SOURCE>
As far as I can tell, the mod times are updating...
# stat -c %x,%z,%n *
2016-12-19 18:13:07.746622111 -0500,2016-12-19 18:13:05.086528147 -0500,estreamer.log.1482188776
2016-12-19 18:18:05.669146138 -0500,2016-12-19 18:17:53.633720988 -0500,estreamer.log.1482189284
2016-12-19 18:20:24.216037498 -0500,2016-12-19 18:20:16.464764117 -0500,estreamer.log.1482189486
2016-12-19 18:39:48.360107852 -0500,2016-12-19 18:39:47.098063317 -0500,estreamer.log.1482189684
Edit 1:
I think eStreamer is keeping the file descriptor open, so mdtm and scrc never get written...
# /services/splunk/bin/splunk cmd btprobe -d /services/splunk/var/lib/splunk/fishbucket/splunk_private_db/ --file /services/splunk/etc/apps/eStreamer/log/estreamer.log.1482202447
Using logging configuration at /services/splunk/etc/log-cmdline.cfg.
key=0x40ebb995eb99a09d scrc=0x0 sptr=0 fcrc=0x8b093ad81b0a8ee3 flen=0 mdtm=0 wrtm=1482205094
# /services/splunk/bin/splunk cmd btprobe -d /services/splunk/var/lib/splunk/fishbucket/splunk_private_db/ -k 0x40ebb995eb99a09d --validate
validation result: OK
key=0x40ebb995eb99a09d scrc=0x0 sptr=0 fcrc=0x8b093ad81b0a8ee3 flen=0 mdtm=0 wrtm=1482205094
# stat -c %x,%z,%n *.log*
2016-12-20 00:00:42.377623768 -0500,2016-12-20 00:00:41.943608425 -0500,estreamer.log.1482202447
# lsof | grep eStream
splunkd 2017 splunk 38u REG 253,0 150083 924551 /services/splunk/etc/apps/eStreamer/log/estreamer.log.1482202447
I wish I could have solved the actual issue, but in the interest of time I was forced to wipe the Splunk instance and start over again. Now things are working as expected.
I wish I could have solved the actual issue, but in the interest of time I was forced to wipe the Splunk instance and start over again. Now things are working as expected.
Additional DEBUG:
12-19-2016 18:48:23.465 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189486'.
12-19-2016 18:48:23.465 -0500 DEBUG WatchedFile - Preserving seekptr and initcrc.
12-19-2016 18:48:23.465 -0500 DEBUG WatchedFile - seeking /services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189486 to off=10757
12-19-2016 18:48:23.465 -0500 DEBUG WatchedFile - Reached EOF: fname=/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189486 fishstate=key=0x5c24e5d7fe922fe4 sptr=10757 scrc=0x0 fnamecrc=0x3a9e53c7b25f00db modtime=1482189616
12-19-2016 18:48:23.467 -0500 DEBUG WatchedFile - Storing pending metadata for file=/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189486, sourcetype=eStreamer, charset=UTF-8
12-19-2016 18:48:23.467 -0500 DEBUG WatchedFile - setting trailing nulls to false via 'true' or 'false' from conf'
12-19-2016 18:48:23.467 -0500 DEBUG WatchedFile - Creating new pipeline input channel with channel id: 258.
12-19-2016 18:48:23.467 -0500 DEBUG WatchedFile - Attempting to load indexed extractions config from conf=source::/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189486|host::llsd-llan1|eStreamer|258 ...
12-19-2016 18:48:23.467 -0500 DEBUG WatchedFile - Loading state from fishbucket.
12-19-2016 18:48:23.467 -0500 DEBUG WatchedFile - /services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189486 requested modtime-based check.
12-19-2016 18:48:23.468 -0500 DEBUG WatchedFile - initcrc has changed to: 0x3a9e53c7b25f00db.
12-19-2016 18:48:23.468 -0500 DEBUG WatchedFile - Comparing current & stored modtime.
12-19-2016 18:48:23.468 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189486'.
12-19-2016 18:48:23.468 -0500 DEBUG WatchedFile - seeking /services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189486 to off=0
12-19-2016 18:48:23.468 -0500 DEBUG WatchedFile - Reading for plain initCrc...
12-19-2016 18:48:23.468 -0500 DEBUG WatchedFile - initcrc changed to 0x5c24e5d7fe922fe4 since file grew past initCrcLen.
12-19-2016 18:48:23.468 -0500 DEBUG WatchedFile - Applying pending meta data
12-19-2016 18:48:23.468 -0500 DEBUG WatchedFile - Clearing pending metadata
12-19-2016 18:48:23.468 -0500 DEBUG WatchedFile - Reached EOF: fname=/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189486 fishstate=key=0x5c24e5d7fe922fe4 sptr=10757 scrc=0x0 fnamecrc=0x3a9e53c7b25f00db modtime=1482189616
12-19-2016 18:48:23.468 -0500 DEBUG WatchedFile - Loading state from fishbucket.
12-19-2016 18:48:23.468 -0500 DEBUG WatchedFile - /services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189284 requested modtime-based check.
12-19-2016 18:48:23.468 -0500 DEBUG WatchedFile - initcrc has changed to: 0x22cf35f531d75c34.
12-19-2016 18:48:23.468 -0500 DEBUG WatchedFile - Comparing current & stored modtime.
12-19-2016 18:48:23.468 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189284'.
12-19-2016 18:48:23.468 -0500 DEBUG WatchedFile - Preserving seekptr and initcrc.
12-19-2016 18:48:23.468 -0500 DEBUG WatchedFile - seeking /services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189284 to off=22567
12-19-2016 18:48:23.469 -0500 DEBUG WatchedFile - Reached EOF: fname=/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189284 fishstate=key=0xa2d8a35900bb8f3f sptr=22567 scrc=0x0 fnamecrc=0x22cf35f531d75c34 modtime=1482189473
12-19-2016 18:48:23.470 -0500 DEBUG WatchedFile - Storing pending metadata for file=/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189284, sourcetype=eStreamer, charset=UTF-8
12-19-2016 18:48:23.470 -0500 DEBUG WatchedFile - setting trailing nulls to false via 'true' or 'false' from conf'
12-19-2016 18:48:23.470 -0500 DEBUG WatchedFile - Creating new pipeline input channel with channel id: 259.
12-19-2016 18:48:23.470 -0500 DEBUG WatchedFile - Attempting to load indexed extractions config from conf=source::/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189284|host::llsd-llan1|eStreamer|259 ...
12-19-2016 18:48:23.470 -0500 DEBUG WatchedFile - Loading state from fishbucket.
12-19-2016 18:48:23.470 -0500 DEBUG WatchedFile - /services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189284 requested modtime-based check.
12-19-2016 18:48:23.471 -0500 DEBUG WatchedFile - initcrc has changed to: 0x22cf35f531d75c34.
12-19-2016 18:48:23.471 -0500 DEBUG WatchedFile - Comparing current & stored modtime.
12-19-2016 18:48:23.471 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189284'.
12-19-2016 18:48:23.471 -0500 DEBUG WatchedFile - seeking /services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189284 to off=0
12-19-2016 18:48:23.471 -0500 DEBUG WatchedFile - Reading for plain initCrc...
12-19-2016 18:48:23.471 -0500 DEBUG WatchedFile - initcrc changed to 0xa2d8a35900bb8f3f since file grew past initCrcLen.
12-19-2016 18:48:23.471 -0500 DEBUG WatchedFile - Applying pending meta data
12-19-2016 18:48:23.471 -0500 DEBUG WatchedFile - Clearing pending metadata
12-19-2016 18:48:23.471 -0500 DEBUG WatchedFile - Reached EOF: fname=/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482189284 fishstate=key=0xa2d8a35900bb8f3f sptr=22567 scrc=0x0 fnamecrc=0x22cf35f531d75c34 modtime=1482189473
12-19-2016 18:48:23.472 -0500 DEBUG WatchedFile - Loading state from fishbucket.
12-19-2016 18:48:23.472 -0500 DEBUG WatchedFile - /services/splunk/etc/apps/eStreamer/log/estreamer.log.1482188776 requested modtime-based check.
12-19-2016 18:48:23.472 -0500 DEBUG WatchedFile - initcrc has changed to: 0x713da102c673468a.
12-19-2016 18:48:23.472 -0500 DEBUG WatchedFile - Comparing current & stored modtime.
12-19-2016 18:48:23.472 -0500 INFO WatchedFile - Will begin reading at offset=0 for file='/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482188776'.
If you have logrotate set up, are you sure it's not doing something funky during the rotate?
It's an eStreamer rotate...so I'm not entirely sure what it is doing in the background 😞
I do know that the modtime for the files aren't being updated, so I think that is why they keep getting fully reindexed:
# /services/splunk/bin/splunk cmd btprobe -d /services/splunk/var/lib/splunk/fishbucket/splunk_private_db/ --file /services/splunk/etc/apps/eStreamer/log/estreamer.log.1482202447
Using logging configuration at /services/splunk/etc/log-cmdline.cfg.
key=0x40ebb995eb99a09d scrc=0x0 sptr=0 fcrc=0x8b093ad81b0a8ee3 flen=0 mdtm=0 wrtm=1482205094
# /services/splunk/bin/splunk cmd btprobe -d /services/splunk/var/lib/splunk/fishbucket/splunk_private_db/ -k 0x40ebb995eb99a09d --validate
validation result: OK
key=0x40ebb995eb99a09d scrc=0x0 sptr=0 fcrc=0x8b093ad81b0a8ee3 flen=0 mdtm=0 wrtm=1482205094
This gives me more info that doesn't seem to be congruent with the btprobe info.
<s:key name="/services/splunk/etc/apps/eStreamer/log/estreamer.log.1482202447">
<s:dict>
<s:key name="file position">150083</s:key>
<s:key name="file size">150083</s:key>
<s:key name="parent">$SPLUNK_HOME/etc/apps/eStreamer/log</s:key>
<s:key name="percent">100.00</s:key>
<s:key name="type">open file</s:key>
</s:dict>
</s:key>
Do NOT use crcSalt. That is the cause of your reindexing. Every time your log file rolls, it gets a new name. The crcSalt setting says to use the name of the file as part of the unique identifier. That's not what you want with rolling files.
crcSalt should be avoided in nearly every case I see people trying to use it in.
I've disabled that as well, since I saw the notes in inputs.conf documentation. It doesn't help. The files still get reindexed.
They would get re-indexed one more time since their hash would change when you stopped including source. But after that, they should stop. I'm not seeing any reason why they'd continue based on the configs provided. Sorry. ¯_(ツ)_/¯
I hope you're right.
New events are still being reindexed over and over...