How to return events in the original, actual sequence as appear in the log file?

[takashi6]

Hello experts and splunkers,

I have batch job log files being indexed into Splunk.

The actual log looks like below.
It's essentially telling JobA started at 5:35:42 and finished at 5:36:12, and JobA again started at 5:36:12 and finished at 5:36:43.

0,2020-02-09T05:36:43,Server1,End,JobA
,2020-02-09T05:36:12,Server1,Start,JobA
0,2020-02-09T05:36:12,Server1,End,JobA
,2020-02-09T05:35:42,Server1,Start,JobA

When the log file is indexed and I search the index, Splunk returns the same 4 events but in a different sequence like below:
0,2020-02-09T05:36:43,Server1,End,JobA
0,2020-02-09T05:36:12,Server1,End,JobA
,2020-02-09T05:36:12,Server1,Start,JobA
,2020-02-09T05:35:42,Server1,Start,JobA

As you can see, the 2nd and 3rd events have the same _time and the sequence is flipped as compared to the original sequence.
It seems Splunk automatically sort the event by _time when returning events.

I need the result returned in the original sequence.
Is there any way to instruct Splunk return events in the original, actual sequence?

[richgalloway · Accepted solution]

Please bear in mind that Splunk is a time-oriented system. Events with the exact same time may or may not be displayed in their original file order.

[takashi6]

Hi @richgalloway - thanks... yeah... I guess I have accept the orientation of the system behavior and move on... Thanks!

[to4kawa]

| makeresults
| eval _raw="0,2020-02-09T05:36:43,Server1,End,JobA
0,2020-02-09T05:36:12,Server1,End,JobA
,2020-02-09T05:36:12,Server1,Start,JobA
,2020-02-09T05:35:42,Server1,Start,JobA"
| rex mode=sed "s/^s*//g"
| eval _raw="No,Timestamp,Server,Status,Job
"._raw
| multikv forceheader=1
| fields No,Timestamp,Server,Status,Job
| eval _time = strptime(Timestamp,"%FT%T")
| sort _time -Status

The Status is END, START in the order of character string.
| sort _time -Status handle the order _time and reverse order Status.

Please convert to your fields name.

see: https://docs.splunk.com/Documentation/Splunk/latest/SearchReference/Sort

[takashi6]

Thank you, @to4kawa, for your effort and help!
Yeah... this works for the particular instance of issue.

However, I realise there are other variation of the same issue.
For example, there are jobs which run only for a fraction of a second and is triggered one after another.
For those, the log may look like below, which is essentially saying:
1) first execution started at 05:36:12 and finished at 05:36:12
2) second execution started at 05:36:12 and finished at 05:36:13

0,2020-02-09T05:36:13,Server1,End,JobA
,2020-02-09T05:36:12,Server1,Start,JobA
0,2020-02-09T05:36:12,Server1,End,JobA
,2020-02-09T05:36:12,Server1,Start,JobA

In this instance, I will end up with a wrong sequence with the given query.

[woodcock]

If you need to reconstitute the original sequence, your best bet is like this:

... | sort 0 - _time - _indextime

[takashi6]

Thank you, @woodcock for your comment.
I tried the query as suggested but the result was exactly the same as before.
I suppose Splunk has exact same timestamp even in the _indextime for the two events which have the same _time.

[richgalloway]

It looks like the events are sorted lexicographically rather than by _time. Have you tried sort - _time?
Have you checked the props.conf settings for the sourcetype to verify the timestamp is correctly identified?

[takashi6]

Hi @richgalloway - thank you for your comment.
Yes, "sort - _time" didn't help...
The problem is the two events having the exact same _time and the Splunk doesn't return the two events in the original sequence.