Table not sorted by time even after specifying the sort, what am I missing?

[leekeener]

I have a search results I want to show in a table. I noticed that the events were not sorted by time so I added the sort _time desc. I just noticed that the time is still off as 12:00 is coming before 01:00 times. What is the fix for this? Should I not be using a table? I like how it formats the results, maybe there is another way? Here is the whole serach, this is on some Electric SCADA data to show uncommanded breaker operations.

sourcetype=escada_message breaker=* AND NOT DELETED AND NOT ACKNOWLEDGD
| eval cmdops=if(operation == "COMMAND TO CLOSE" OR operation == "COMMAND TO OPEN" OR operation == "CONTROL TO CLOSE" OR operation == "CONTROL TO OPEN", 1, 0)
| eval uncmdops=if(operation == "OPEN" OR operation == "CLOSE" OR operation == "OPEN-CLOSE" OR operation == "CLOSE-OPEN" OR operation == "OPEN-CLOSE-OPEN" OR operation == "CLOSE-OPEN-CLOSE", 1, 0)
| eval totalcmd= if(operation == "COMMAND TO CLOSE" OR operation == "COMMAND TO OPEN" OR operation == "CONTROL TO CLOSE" OR operation == "CONTROL TO OPEN" OR
operation == "OPEN" OR operation == "CLOSE" OR operation == "OPEN-CLOSE" OR operation == "CLOSE-OPEN" OR operation == "OPEN-CLOSE-OPEN" OR operation == "CLOSE-OPEN-CLOSE",1,0)
| eval errors=if(operation == "Clearance" OR operation == "FAIL*" OR operation == "OVERIDE*" OR operation == "SET*", 1, 0)
| search uncmdops>0
| sort - _time
| table _time breaker operation

[leekeener · Accepted solution]

I figured this out and you will not believe what it was. The fix was to use strptime and format it to show AM and PM, the 12:xx times were PM, not AM. I was quite amused by how the data was just so to prevent this from being a question you'd ask. Thanks for everyone's help.

[to4kawa]

sourcetype=escada_message (breaker=* NOT "DELETED" NOT "ACKNOWLEDGD")
| eval cmdops=if(match(operation,"(COMMAND|CONTROL) TO (CLOSE|OPEN)"), 1, 0)
| eval uncmdops=if(match(operation,"^(CLOSE|OPEN)(\-\1)?(\-\1)?"), 1, 0)
| eval totalcmd= coalesce(cmdops,uncmdops)
| eval errors=if(IN(operation,"Clearance","FAIL","OVERIDE*","SET*"), 1, 0)
| search uncmdops > 0
| sort - _time
| table _time breaker operation

It ’s not the purpose of the question, but the query can be written in easy way.

[woodcock]

One problem is that you should never use sort without a number because doing so causes it to truncate your results set: so always use sort 0. The other problem I suspect is an admin problem with data onboarding. Sometimes people get very lazy and use DATETIME_CONFIG = CURRENT or DATETIME_CONFIG = NONE because they are lazy or they desire to use the should-never-be-used realtime features. Probably this was what was done for your sourcetype and the reason that you think the events are out of order is because that is how they were indexed. You are looking at the timestamp in the event (shown in the _raw field) but that was not used for the actual timestamp. This is just a theory; you have not given us enough detail to be conclusive.

[to4kawa]

| makeresults
| eval _raw="
_time               breaker operation
2019-12-30 12:51:24 RH31B CLOSE-OPEN
2019-12-30 12:50:08 RH31B CLOSE-OPEN
2019-12-30 12:49:28 RH31B OPEN
2019-12-30 12:49:24 RH31B OPEN-CLOSE
2019-12-30 01:43:01 KR12B CLOSE
2019-12-30 01:42:18 KR12B OPEN
2019-12-30 01:42:16 KR12B OPEN-CLOSE
2019-12-30 01:35:12 KX12B OPEN
2019-12-30 01:35:09 KX12B CLOSE"
| multikv forceheader=1
| eval time_h=strptime(time,"%F %H:%M:%S")
| eval time_i=strptime(time,"%F %I:%M:%S")
| table time* breaker operation

Hi, @leekeener
I think this situation is because the log time is recognized by %H.

You need to review the settings in props.conf.

[kamlesh_vaghela]

@leekeener

I'm sure table is not the problem and not | sort - _time as well. You can confirm it by executing below search for 5 min.

index=_internal | sort - _time  | table _time _raw

Can you please share some sample events OR present output ( as screenshot) and expected output ?

[leekeener]

I would love to share a screenshot, however I don't see how to do so. I can provide a link to an image, but I've no means to host the image for linkiing

[richgalloway]

_time is a special field that exists as an integer, but is automatically displayed as text. Sorting on _time should always result in events displaying in time sequence (ascending or descending). Note that Splunk's default behavior is to display events in reverse chronological order (newest first) and the reverse command will put them in chronological order (oldest first).

If this doesn't help, please edit your question to include an example of the current output.

[leekeener]

Thanks for the help. I agree with everything you said yet I am getting these results: Most recent event should be the 1:34am one. I use a similar search in a bunch of reports so there was some superfluous stuff. A more concise search is at the bottom, this produced the results below.

2019-12-30 12:51:24 RH31B CLOSE-OPEN
2019-12-30 12:50:08 RH31B CLOSE-OPEN
2019-12-30 12:49:28 RH31B OPEN
2019-12-30 12:49:24 RH31B OPEN-CLOSE
2019-12-30 01:43:01 KR12B CLOSE
2019-12-30 01:42:18 KR12B OPEN
2019-12-30 01:42:16 KR12B OPEN-CLOSE
2019-12-30 01:35:12 KX12B OPEN
2019-12-30 01:35:09 KX12B CLOSE

Search:
sourcetype=escada_message breaker=* AND NOT DELETED AND NOT ACKNOWLEDGD
| eval uncmdops=if(operation == "OPEN" OR operation == "CLOSE" OR operation == "OPEN-CLOSE" OR operation == "CLOSE-OPEN" OR operation == "OPEN-CLOSE-OPEN" OR operation == "CLOSE-OPEN-CLOSE", 1, 0)
| search uncmdops>0
| sort - _time
| table _time breaker operation