Occasional screwy (future) timestamps

[grijhwani]

Running Enterprise 5.0.5, and encountering a very odd bug. (Yes, I will be upgrading to 5.0.8, some time in near future, but no, not version 6.)

The following log extract:

Jun 26 00:46:13 machine postfix/cleanup[28422]: 893A657: message-id=<20140625234613.893A657@machine.domain>
Jun 26 00:46:13 machine postfix/cleanup[28422]: 9883258: message-id=<20140625234613.9883258@machine.domain>
Jun 26 01:46:13 machine postfix/pickup[23642]: 8AA5C57: uid=101 from=<sender>
Jun 26 01:46:13 machine postfix/qmgr[22425]: 8AA5C57: from=<sender@machine.domain>, size=839, nrcpt=1 (queue active)
Jun 26 01:46:13 machine postfix/local[8284]: 8AA5C57: to=<0@machine.domain>, orig_to=<0>, relay=local, delay=0.07, delays=0.04/0.01/0/0.02, dsn=5.1.1, status=bounced (unknown user: "0")
Jun 26 01:46:13 machine postfix/bounce[8287]: 8AA5C57: sender non-delivery notification: 98B1158
Jun 26 01:46:13 machine postfix/qmgr[22425]: 98B1158: from=<>, size=2818, nrcpt=1 (queue active)
Jun 26 01:46:13 machine postfix/qmgr[22425]: 8AA5C57: removed
Jun 26 01:46:13 machine postfix/local[8284]: 98B1158: to=<sender@machine.domain>, relay=local, delay=0.02, delays=0/0/0/0.02, dsn=2.0.0, status=sent (delivered to mailbox)
Jun 26 01:46:13 machine postfix/qmgr[22425]: 98B1158: removed

...leads to the following events indexed in the future:

26/06/2014 23:46:13.988 Jun 26 00:46:13 machine postfix/cleanup[28422]: 9883258: message-id=<20140625234613.9883258@machine.domain>
26/06/2014 23:46:13.893     Jun 26 00:46:13 machine postfix/cleanup[28422]: 893A657: message-id=<20140625234613.893A657@machine.domain>

We see this in some Windows logs, too. It seems that the time is being inferred (to milliseconds) from an embedded message-id whenever one is detected, in preference to the actual stamp of the event. The other entries in the log are correctly indexed. We have similar instances of another type of logging where the time is being inferred as above, but is also being "corrected" for UTC (which currently puts it an hour back) but indexed by the current date (which then leads to it being indexed 23 hours in the future).

I'm just wondering if this is (these are) a known bug, corrected in later releases? Specifically is it correct in 5.0.8?

[abonuccelli_spl]

Assuming your events are broken correctly,

e.g. 20140625234613.893A657@machine.domain does not create a new event on its own

you can override default MAX_TIMESTAMP_LOOKAHEAD(=150) for this source type to something shorter (e.g. 15/20) so that Splunk won't even get that far when looking for event timestamps

see http://docs.splunk.com/Documentation/Splunk/6.1.1/Data/Configurepositionaltimestampextraction

link text

[grijhwani]

What I don't understand is why it would choose to look for embedded data for an event which is already explicitly timestamped. This is just one example data source where this happens. It seems to happen a lot in the Windows exchange logs. For some reason it seems to have an unreasonable affinity for message-ids as timestamps over that of the actual log record.