All Apps and Add-ons

Cisco eStreamer for Splunk: Why does Splunk keep reindexing monitored SourceFire eStreamer logs?

Path Finder

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
0 Karma
1 Solution

Path Finder

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.

View solution in original post

0 Karma

Path Finder

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.

View solution in original post

0 Karma

Path Finder

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'.
0 Karma

Motivator

If you have logrotate set up, are you sure it's not doing something funky during the rotate?

0 Karma

Path Finder

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
0 Karma

Path Finder

This gives me more info that doesn't seem to be congruent with the btprobe info.

/services/splunk/bin/splunk _internal call /services/admin/inputstatus/TailingProcessor:FileStatus

            <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>
0 Karma

Influencer

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.

0 Karma

Path Finder

I've disabled that as well, since I saw the notes in inputs.conf documentation. It doesn't help. The files still get reindexed.

0 Karma

Influencer

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. ¯_(ツ)_/¯

0 Karma

Path Finder

I hope you're right.

New events are still being reindexed over and over...

0 Karma