Converting log time into a usable format

[bcarr12]

I am trying to use Splunk to determine if there is a delay in processing from one of the logs being consumed. The delay would be determined by taking the actual log file time (_time) and having it subtracted from a time within the logfile itself. The problem is that the time value in the log files themselves are in a "non-standard" format

The log file is in this format for AM:
61659 (no leading 0) (ie 06:16:59)

and this format for PM:
160553 (ie 16:05:53)

Is there any way to convert these values into a format that Splunk could treat as a time, in order to compare against _time (or vice versa?)

[kristian_kolb]

If everything goes well with the parsing of timestamps, _time and the timestamp in the event will be the same - adjusted for TZ.

If Splunk does not understand the timestamp, there are a few fallbacks (modtime of source file, timestamp of previous event, local time on indexer).

In your case, you might want to explain to splunk how your timestamp is to be parsed. This is done in the TIME_FORMAT parameter in props.conf.

[your_sourcetype]
TIME_FORMAT = %k%M%S

You most likely want to add the date variables to that parameter as well, if they exist in your log. Post some sample events if you want help with this, it's always a good idea.

For more info on timestamp variables and how Splunk identifies timestamps, see;
www.strftime.net
http://docs.splunk.com/Documentation/Splunk/5.0.3/Data/HowSplunkextractstimestamps
http://docs.splunk.com/Documentation/Splunk/5.0.3/Data/Configuretimestamprecognition

NB: If you want to check indexing lag, i.e. the difference between the creation of an event, and the time it is indexed in splunk, you need to look at the _indextime field, e.g.;

your search | eval lag = _indextime - _time | stats avg(lag) by host

---

UPDATE:

I'm sorry.

The log occurred at the timestamp in the event. By definition, there is no difference. And if there was, there is no way for you to know.

A program experiences an event 'X' that is supposed to be printed as a line of log in a file. However, it does not do that immediately (at time T), but waits a few minutes and then writes it to file (at time T+5), setting the timestamp in the event to T+5. How could you know when 'X' really happened? If you have such doubts regarding the quality of your data, you probably have bigger issues to deal with than this.

Moving back into the realm of the possible, here is what Splunk will provide you with for your time computing needs. There are four types of time 'objects' in each event;

1) the timestamp in the event which can look pretty much like anything

2) _time which is how Splunk parsed the timestamp (1). This is expressed as epoch. Also, _time will be adjusted if there is TZ information either in timestamp (1), or in props.conf for type of data. Usually this goes well. But sometimes you need to give Splunk a nudge. _time is also what is printed next to each event when they are presented as search results (but in a nicer format than epoch).

3) _indextime is the system time of the indexer, when this particular event was indexed. Also in epoch.

4) the date_*-fields, which is the parsed timestamp (1) broken into its individual pieces, i.e. year, hour, second etc. This does read the event data literally, and does not take any TZ information into account. Strings and/or numbers.

---

UPDATE:

Does the little timestamp beside the event (on the left side) correspond to the timestamp within the event?

If "YES", then the parsing of the timestamp is correct, and there will be no differences because they are the same - although the presentation of the timestamps may differ, e.g. 12-hour vs 24-hour clock.

If "NO", then you need to fix your parsing of the timestamp, or configure your logging, so that a more complete timestamp is logged.

What you CAN measure is indexing lag, which is the difference between _indextime and _time. _indextime is not normally shown anywhere, so you'll have to evaluate it like so;

... | eval lag = _indextime - _time

Hope this helps,

Kristian

[bcarr12]

Apologies as the logs have proprietary information so I can't paste them verbatim. Ehat I am trying to do is compare a time within the log file against _time to determine if there is a delay in processing the given action in that log (_time-logfield=duration to process). Ideally this should be 0, any number greater is a "delay".

I believe I have figured out how to go about doing this, but the conversion is still not working out properly. For instance:
eval logfield=strftime(logfield, "%k%M%S"). The only problem is, using this command is converting "82213" to "175013", any thoughts?

[kristian_kolb]

see update above, and read up on the docs. Also, it might prove beneficial if you could provide some sample events, and a sketch of your desired output.

[bcarr12]

Ultimately the logs are trying to determine the time between when an event in the log occurred, and the log timestamp itself. Is there something I can do ad-hoc at searchtime to take make _time match the formats in the logs (61659 and 160553 for instance) so they can be compared? I am familiar with strftime but I think the problem is I need to keep the values as times in order to properly subtract them from eachother?