Timestamp has correct time, incorrect date for some events

[jamesv84]

I am adding data from a log file with filename: C:\init97\log\mpinet_init97-20120414-000004.mlg

For the timestamp, some events have the correct timestamp of 4/14/12 + the event time in the log file. Other events, however, have an incorrect timestamp with a date that is in the future. For example, 4/17/12 + event time from log.

The event time always seems to be correct. It is the date that is correct for some, incorrect for others, within the same file.

An example of an event with a correct timestamp is:
00:50:13 [02535] WARN javax.management.remote.generic: JMX connector transport got exception when reading input message: java.net.SocketException: Connection reset
... This gets a timestamp of 4/14/12 12:50:13.000 AM

An example of an event with an incorrect timestamp is:
13:43:56 [00171] ERROR atesystems.hub.logging.NativeLog: MAD_DbxDisconnect: MAD_OdbcFreeEnv() failed, ignored.
... This gets a timestamp of 4/17/12 1:43:56.000 PM

I tried creating a custom datetime.xml, but it didnt fix the issue. It is using only the following datetime definition:

<!-- ... 20060502-000002 ... -->
<![CDATA[(?<![\d\.])(20\d\d)(0\d|1[012])([012]\d|3[01])[.-]?([01]\d|2[0123])([0-6]\d)([0-6]\d)]]>

I also tried setting the timezone as TZ = US/Central. This too did not fix the issue.

Can anyone help?

[jamesv84]

I tried adding those entries to props.conf, but kept getting the same results.

My props.conf looks like this:

[INIT2]
NO_BINARY_CHECK = 1
TIME_FORMAT = %H:%M:%S
pulldown_type = 1
TZ = US/Central
DATETIME_CONFIG = C:/Program Files/Splunk/etc/system/local/datetime.xml
MAX_TIMESTAMP_LOOKAHEAD = 10

... However, I tried adding a new sourcetype that treats every line as an event. (SHOULD_LINEMERGE = false is the major difference) It looks like:

[INIT3]
DATETIME_CONFIG = C:/Program Files/Splunk/etc/system/local/datetime.xml
MAX_TIMESTAMP_LOOKAHEAD = 10
NO_BINARY_CHECK = 1
SHOULD_LINEMERGE = false
TIME_FORMAT = %H:%M:%S
TZ = US/Central
pulldown_type = 1

I applied this to the file, and it looks much better. The only line that has an incorrect date now is the first line in the log file:

-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= Version 9.7.0.128 -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
... This has a timestamp of 4/16/12 11:59:29.000 AM, but I think I can live with this being the only line with an incorrect timestamp, since it contains no useful logging information.

Obviously for this line, it cannot find a %H:%M:%S timestamp. Can anyone tell me what Splunk is doing for this line in this scenario?

[wrangler2x]

You could drop the Version line by having a transform like this:

[remove_comment]
REGEX = ^-=-=-=
DEST_KEY = queue
FORMAT = nullQueue

And have it be the first transform called-out in the props.conf entry for this sourcetype or input.

[kristian_kolb]

It will index it and probably set the date/time of the event to the local time of the indexer. Hopefully. If you wish, you can look in splunkd.log for DateParserVerbose messages. This is the component responsible for identifying and extracting timestamps. Most likely, a line which has no time information (according to the TIME_FORMAT) will generate an error.

/k

[kristian_kolb]

Hi,

Given your messages, this is what I believe is happening - there is no DATE in the log events whatsoever, and splunk tries to find data within the events that can be parsed as dates. Sometimes this fails - and splunk sets the system date (or file mod-time) as the date for the indexed event. Some other times it "succeeds", i.e. it finds a string that could be parsed as a date, and splunk then uses that, with strange results.

What you could/should do is,

1) Change the logging to include date information as well (if within your control).
2) Explicitly instruct splunk that there is no date information within the events:

in props.conf add the following

[your_sourcetype]
TIME_FORMAT = %H:%M:%S
MAX_TIMESTAMP_LOOKAHEAD = 10

Hope this helps,

Kristian

PS. You can look at the default extracted fields timestartpos and timeendpos to see where splunk thinks your timestamps begin and end. Click on them in the field list to the left in the main search GUI (after searching for your events) You will probably find that the timeendpos will be different wherever splunk has indexed data at the wrong date.