Why is my forwarder sending data from monitored files twice just a couple minutes apart?

[redc]

I just set up a new forwarder on a new Linux server and set it to monitor some files. For some reason, it is sending the data to the indexer twice; I haven't been able to figure out why.

Here's my inputs.conf:

[monitor:/mnt/swift/accounts/*/logfiles/*Queued.log]
ignoreOlderThan = 1d
index = mta-logs_queued
sourcetype = mta-logs_queued
disabled = 0

[monitor:/mnt/swift/accounts/*/logfiles/*Deferred.log]
ignoreOlderThan = 1d
sourcetype = mta-logs_deferred
index = mta-logs_deferred
disabled = 0

[monitor:/mnt/swift/accounts/*/logfiles/*Processed.log]
ignoreOlderThan = 1d
sourcetype = mta-logs_processed
index = mta-logs_processed
disabled = 0

And my props.conf:

[mta-logs_queued]
INDEXED_EXTRACTIONS=csv
NO_BINARY_CHECK=1
SHOULD_LINEMERGE=false
KV_MODE=none
PREAMBLE_REGEX=#
HEADER_FIELD_DELIMITER=,
FIELD_NAMES=Date,Time,EventType,SystemMessageId,CustomMessageId,MailingID,To,From,Size
TIMESTAMP_FIELDS=Date,Time
TIME_FORMAT=%m/%d/%Y %H:%M:%S
TZ=America/Chicago
FIELD_DELIMITER=space

[mta-logs_processed]
INDEXED_EXTRACTIONS=csv
NO_BINARY_CHECK=1
SHOULD_LINEMERGE=false
KV_MODE=none
PREAMBLE_REGEX=#
HEADER_FIELD_DELIMITER=,
FIELD_NAMES=Date,Time,EventType,SystemMessageId,CustomMessageId,MailingID,To,From,Size,ConnectionId,Reason,Message,LocalIp,FailureCode
TIMESTAMP_FIELDS=Date,Time
TIME_FORMAT=%m/%d/%Y %H:%M:%S
TZ=America/Chicago
FIELD_DELIMITER=space

[mta-logs_deferred]
INDEXED_EXTRACTIONS=csv
NO_BINARY_CHECK=1
SHOULD_LINEMERGE=false
KV_MODE=none
PREAMBLE_REGEX=#
HEADER_FIELD_DELIMITER=,
FIELD_NAMES=Date,Time,EventType,SystemMessageId,CustomMessageId,MailingID,To/Domain,From,Size/Count,ConnectionId,Reason,LocalIP
TIMESTAMP_FIELDS=Date,Time
TIME_FORMAT=%m/%d/%Y %H:%M:%S
TZ=America/Chicago
FIELD_DELIMITER=space

Sample raw data:

#Software: SocketLabs, Inc. Hurricane Server.
#Version: 1.0.0.917
#Date: 1/28/2015 00:00:08
#Account: 1000
#Fields: Date Time EventType SystemMessageId CustomMessageId MailingID To From Size
1/28/2015 15:08:02 Queued 6e000000199d02 - - recipient@domain.com sender@domain.com 464

#Software: SocketLabs, Inc. Hurricane Server.
#Version: 1.0.0.917
#Date: 1/28/2015 00:00:09
#Account: 1000
#Fields: Date Time EventType SystemMessageId CustomMessageId MailingID To From Size ConnectionId Reason Message LocalIp FailureCode
1/28/2015 15:08:03 Sent 6e000000199d02 - - recipient@domain.com sender@domain.com 464 6e000000088f08 250+2.5.0+Ok - 10.110.76.77 -

Sample expected event group:

1/28/2015 15:08:02 Queued 6e000000199d02 - - recipient@domain.com sender@domain.com 464
1/28/2015 15:08:03 Sent 6e000000199d02 - - recipient@domain.com sender@domain.com 464 6e000000088f08 250+2.5.0+Ok - 10.110.76.77 -

Sample actual event group:

1/28/2015 15:08:02 Queued 6e000000199d02 - - recipient@domain.com sender@domain.com 464
1/28/2015 15:08:02 Queued 6e000000199d02 - - recipient@domain.com sender@domain.com 464
1/28/2015 15:08:03 Sent 6e000000199d02 - - recipient@domain.com sender@domain.com 464 6e000000088f08 250+2.5.0+Ok - 10.110.76.77 -
1/28/2015 15:08:03 Sent 6e000000199d02 - - recipient@domain.com sender@domain.com 464 6e000000088f08 250+2.5.0+Ok - 10.110.76.77 -

From the splunkd.log:

01-28-2015 14:11:53.156 -0600 INFO  TailingProcessor - Parsing configuration stanza: monitor:/mnt/swift/accounts/*/logfiles/*Deferred.log.
01-28-2015 14:11:53.156 -0600 INFO  TailingProcessor - Parsing configuration stanza: monitor:/mnt/swift/accounts/*/logfiles/*Processed.log.
01-28-2015 14:11:53.156 -0600 INFO  TailingProcessor - Parsing configuration stanza: monitor:/mnt/swift/accounts/*/logfiles/*Queued.log.
01-28-2015 14:11:53.156 -0600 INFO  TailingProcessor - Adding watch on path: /mnt/swift/accounts.
01-28-2015 15:08:07.229 -0600 INFO  WatchedFile - Resetting fd  to re-extract header.
01-28-2015 15:08:07.233 -0600 INFO  WatchedFile - Resetting fd  to re-extract header.

I also see some lines in this log, Checksum for seekptr didn't match, will re-read entire file='/mnt/swift/accounts/1034/logfiles/20150128Deferred.log'. (but the timestamps don't seem to line up the way the "Resetting fd" ones above do). This is 100% unrelated to the duplicated data. Something's wrong with that particular file.

The inputs are not duplicated anywhere, they live ONLY in /opt/splunkforwarder/etc/system/local/inputs.conf on the forwarder. Ditto with props.conf.

The duplication isn't instantaneous: the first copy of the events comes in, and a couple minutes later, the duplicates show up.

This is the first time I've used the w3c extraction type, so maybe I've configured something wrong?

I'm running Splunk 6.1.2, the forwarder is 6.0.

[redc · Accepted solution]

After several hours on the phone and a few webex sessions with Splunk support, the conclusion is: DON'T try to forward logs sourced from a Windows server through a Samba share on a Linux server running a UF.

It seems that something about the Samba share transfer process munges the data and prevents it from being properly parsed by either the forwarder or the indexer: if props.conf was configured on the UF, it would do the reindexing thing; if props.conf was configured on the indexer, it couldn't do regex on the data and kept indexing the headers, no matter how many different ways we tried to write the regex to suppress the headers.

I put a Windows UF on the Windows server that was the ultimate source of the logs and set it to forward the logs and everything works perfectly.

(For those who are curious about why we did it the way we had: we're about 90% Linux and none of us like touching the Windows servers any more than is absolutely necessary...they're twitchy and easily frightened (read: broken). I needed a UF on the Linux server in question anyway, so I thought I'd kill two birds with one stone and avoid touching the Windows server as a bonus. Really, REALLY did not work.)

[martin_mueller]

The WatchedFile - Resetting fd to re-extract header. message sounds ominous and lines up with your duplicated events' timestamps - consider upping the loglevel on WatchedFile to learn more, or find someone who knows what this event means 🙂

[martin_mueller]

The checksum event suggests some parts of the file changed that the forwarder didn't expect to change, ie the first 256 bytes or the most recently read 256 bytes. Those are checksum'd and compared to a stored checksum to detect log rotation and other swaps of the file. If the checksums match it'll keep tailing, if they don't it'll start over.

In other words, make sure that file is only appended to.

[redc]

I've confirmed that the checksum error is completely unrelated to the duplication problem.

[redc]

Yes, the file is only appended to.

I was thinking about it some this morning. Given the "Resetting fd to re-extract header" message, I believe the problem is that the header is at the top of the file and the file is being appended to (at the end of the file) - that it's causing the forwarder to have to go back to the top of the file to retrieve the header for the field extraction that is occurring, which then causes it to re-read the entire file. I'm going add the FIELD_NAMES parameter to the props.conf entry, see if that does it.

EDIT: I've messed around with the props.conf quite a bit now and I'm having no luck. I'm still getting the "Resetting fd to re-extract header" message. New props.conf edited into original message...

[redc]

I'm only getting the checksum error on one file, and none of its data has been indexed at all (that file is generating some other errors later on), so I don't think that error is at all related to the duplicate data.