Date on first line of log - time in event - jump in 5 hours causes splunk to misinterpret timestamp

[cpt12tech]

I'm trying to get logs time stamped correctly in Splunk. The format of the logs is one line per event, each line has a time stamp. There is a date stamp at the top of the log.

In one of the logs, the time stamp jumps from 00:58:16.156 to 05:59:15.281. For some reason Splunk is interpreting the timestamp as 1 day earlier?

It's the 40th event down in the log... so 40 good interpretations, and after a 5 hour jump Splunk thinks it's 1 day earlier?

Here is the first line of the log:
Splunk Preview Log
4/18/13 12:00:00.000 AM 18/04/2013 - 00:33:51.828 - LOG OPENED - CHANGE OF DATE

The rest of the log only has time stamp at the beginning:
37 4/18/13 12:58:16.156 AM 00:58:16.156 +263852 closing dst socket...
38 4/18/13 12:58:16.156 AM 00:58:16.156 +263852 closing dst size socket...
39 4/17/13 5:59:15.281 AM 05:59:15.281 +Adding dub job 263853 ...
40 4/17/13 5:59:15.359 AM 05:59:15.359 +Trying to add
41 4/17/13 5:59:15.359 AM 05:59:15.359 ++263853 Connected to source

If I set the MAX_DAYS_AGO = 1
Splunk attempts to interpret the time stamp as 4/17/2013, but because it is outside the date range, instead sets the date time to the last time stamp.
Which gives me 1,980 events all at one time making the log useless.

I've tried:
• setting Timestamp never extends more than 13 chars into the event.
• setting the strptime format as %d/%m/%Y (this picks up the date at the top of the log, but then fails for the timestamps (yellow triangle) and yet recognizes them (green highlight).
• setting the strptime format as %h:%m:%s.%3N: this doesn't work for the timestamps in the log & fails for the date at the top of the log. Yet Splunk recognizes them (green highlight)
• prefexing Timestamp by a pattern of +, recognizes both DateStamp & TimeStamps with no errors, however, same issue of setting time back a day after 5 hour jump in log.

Any other ideas out there on how to get this set up?

---

The way this equipment is set to log, is create 1 file per day. The logs are named Day_05.txt, Day_06.txt. I checked some of the other log files and there are no problems getting the data in correctly.

It appears that there is something with Splunk that doesn't like going from a 00 hour to a 05 hour and it causes misinterpretation of the date, if there is no date included with the time stamp.

Not sure if there is something I can look for in the Splunk logs that would confirm this theory.

---

Just did a test by modifying a test file and adding date in front of each time stamp. Was interpreted correctly.
18/04/2013 - 00:33:51.828 - LOG OPENED - CHANGE OF DATE

18/04/2013 00:33:51.828 +Adding dub job 263851 ...
18/04/2013 00:33:51.906 +Trying to add
18/04/2013 05:59:15.281 +Adding dub job 263853 ...
18/04/2013 05:59:15.359 +Trying to add

---

Another test by incrementing the time by 1 hour increments. Interpreted correctly.
18/04/2013 - 00:33:51.828 - LOG OPENED - CHANGE OF DATE

00:33:51.828 +Adding dub job 263851 ...
01:33:51.906 +Trying to add
02:59:15.281 +Adding dub job 263853 ...
03:59:15.359 +Trying to add
04:33:51.828 +Adding dub job 263851 ...
05:59:15.359 +Trying to add

---

Tested a log file with 6 entries, with the last entry jumping from 00 hour on the 1st entry to 05 on the last entry. Interpretation failed. The left time stamp is from the Splunk preview:
2 4/18/13 12:33:51.828 AM 18/04/2013 - 00:33:51.828 - LOG OPENED - CHANGE OF DATE
3 4/18/13 12:33:51.828 AM 00:33:51.828 +Adding dub job 263851 ...
4 4/18/13 12:33:51.906 AM 00:33:51.906 +Trying to add
5 4/18/13 12:59:15.281 AM 00:59:15.281 +Adding dub job 263853 ...
6 4/18/13 12:59:15.359 AM 00:59:15.359 +Trying to add
7 4/18/13 12:33:51.828 AM 00:33:51.828 +Adding dub job 263851 ...
8 4/17/13 5:59:15.359 AM 05:59:15.359 +Trying to add
9 4/19/13 12:00:09.812 AM 19/04/2013 - 00:00:09.812 - LOG CLOSED - CHANGE OF DATE

---

Another test going back one hour at a time before the 05 hour mark. 04, failed. However, 03 worked.
2 4/18/13 12:33:51.828 AM 18/04/2013 - 00:33:51.828 - LOG OPENED - CHANGE OF DATE
3 4/18/13 12:33:51.828 AM 00:33:51.828 +Adding dub job 263851 ...
4 4/18/13 12:33:51.906 AM 00:33:51.906 +Trying to add
5 4/18/13 12:59:15.281 AM 00:59:15.281 +Adding dub job 263853 ...
6 4/18/13 12:59:15.359 AM 00:59:15.359 +Trying to add
7 4/18/13 3:33:51.828 AM 03:33:51.828 +Adding dub job 263851 ...
8 4/18/13 5:59:15.359 AM 05:59:15.359 +Trying to add

9 4/19/13 12:00:09.812 AM 19/04/2013 - 00:00:09.812 - LOG CLOSED - CHANGE OF DATE

On a smaller file with 00 hour and one 05 hour, I put in a timestamp format as %H:%M:%s, and it worked. However, %h:%m:%s does not work. When I tried to apply %H:%M:%s to the full file, it did not work. Not sure why an upper case would work and lower would not work... still looking for that answer.

Noticed in the splunk datetime.xml CDATA for extracting hour is

<text><![CDATA[([01]?[1-9]|[012][0-3])(?!\d)]]></text>

Not sure how to look or read this yet, but am noticing 0-3, which will parse correctly in my files, but going from 0 to 4 or 5 will not work.

---

Tried modifying the datetime.xml to be 0-9. No Improvement.
Also tried changing 0-3 to 0-5, although I don't think this has anything do do with the issue. No Improvement.

What's odd about this issue is that Splunk is recognizing the timestamp. I've seen some instances where a time stamp is not recognized and Splunk defaults back to the previous timestamp. This would mean Splunk is keeping a running date/time stamp for previous events in a file and possible use this to help determine the timestamp.

[cpt12tech]

Still having this problem... Seems like there should be a way to tell splunk to treat entries from a file with the day name in the title, and date in the 1st line that all time entries in that file are from that day?

If the file is named Day_28.txt
all the time entries in the file are being recorded as July 27.

[cpt12tech]

The equipment generating the logs is for video automation software. I contacted the developers to see if there was a way to add a date to each line in the log and they responded not in the version we have.

[wrangler2x]

I found a splunk question where another person was having the same problem. Take a look and try what is suggested there, and see if it helps.

Timestamp has correct time, incorrect date for some events

or

http://splunk-base.splunk.com/answers/45629/timestamp-has-correct-time-incorrect-date-for-some-event...

[kasu_praveen]

Did any one get this working?

[cpt12tech]

The timestartpos is 0 & timeendpos is 12. All the events show this with the exception of the 1st & last, which have no timestamp. The timeendpos is 26 for those.

[cpt12tech]

also tried:
%H.%M.%S.%L Same results.

[cpt12tech]

Thank you for the responses.

I've tried both Time_format and different variations of the MAX_TIMESTAMP_LOOKAHEAD. Same results.

Using %T.%L and had same results. I've been using %H:%M:%S.%3N for microseconds.

Line 37 is correct as Splunk is interpreting it from a 24 hour clock. 00:58 is 12:58 AM.

The files are named Day_01.txt, Day_02.txt, and are overwritten on a Monthly basis by the day of month. If Splunk was using the file mod date, it would be 1 day ahead for previous files, and time of current day for current files.

[wrangler2x]

Information on how Splunk assigns timestamps may be found here: http://docs.splunk.com/Documentation/Splunk/latest/Data/HowSplunkextractstimestamps

An interesting point there is that for file sources if there is no date in the file's name, splunk uses the files modification time for the date when there is no date on the event. How are the files named?

[wrangler2x]

Also, looking at your sample again I find it confusing:

37 4/18/13 12:58:16.156 AM 00:58:16.156 +263852 closing dst socket...
[snippage]
39 4/17/13 5:59:15.281 AM 05:59:15.281 +Adding dub job 263853 ...

Looks like line 37 has a timestamp of 00:58 but splunk is interpreting it as 12:58 -- a 12 hour difference. What time zone is the log entry and what is your local time zone?

And yet line 39 shows a timestamp of 05:59 and splunk interprets that as the same -- 5:59, but now 24 hours earlier (thus date change). Something very odd about that.

[wrangler2x]

I realize they are links to the same page. One is linked via subject, the other via the actual link. Just trying to be clear.

I understand the format of your log file.

Did you do both the TIME_FORMAT and the MAX_TIMESTAMP_LOOKAHEAD?

So in the case where your log goes from 0 to 5 (and the date changes), do a search and take a look at timestartpos and timeendpos to see what those values are. That would be interesting info.

Now as to your time format in the log data, you show it as

00:33:51.828

and that is %T.%L (local time with decimal fraction).
http://apidock.com/ruby/DateTime/strftime

[cpt12tech]

Both of those links are to the same question.

They didn't help with solving the issue. I have a date inside of the file, it's on the first line. However, the rest of the log is in time.

18/04/2013 - 00:33:51.828 - LOG OPENED - CHANGE OF DATE

00:58:13.109 +263852 Verified copied file size Source: Archive E/TR11239.mxf,
00:58:16.156 +263852 closing src socket...
00:58:16.156 +263852 closing dst socket...
00:58:16.156 +263852 closing dst size socket...
05:59:15.281 +Adding dub job 263853 ...

[wrangler2x]

I see. I was going to say that if it was coming in through syslog that you could rewrite the header for the log entries to have a proper date and time timestamp. Perhaps the format is configurable on what ever is generating the logs. That would be easiest.

[cpt12tech]

Through a shared network folder using Data Inputs (files)

[wrangler2x]

How are you transferring these logs to splunk?