How do you group Start and End times from a set of log lines?

[nareshinsvu]

Hi,

I have a logfile content like below. I have 3 lines per event (sometime more than 3). But each event has a unique identifier/counter "5" as in ([https-openssl-apr-443-exec-5]). The next event can use the same identifier. But the next event on the same identifier starts only after "Transaction end" of current identifier. And the log might not have these events captured in the sequence shown below. There might be 2 events starting at the same time and might finish at different timings.

Requirement: to create a table with "request[ref-17271928]" , "message type [setup]", Start-time and End-time.

Here an identifier plays a key role.

I am assuming that I need to use a Heavy forwarder. I have only used a universal forwarder until now for my previous use cases which are not this complex. Any help is much appreciated.

2019-01-08_00:00:36.763 [https-openssl-apr-443-exec-5] DEBUG Transaction Start : 
2019-01-08_00:00:36.872 [https-openssl-apr-443-exec-5] INFO  successfuly saved request[ref-17271928] of message type [setup].
2019-01-08_00:00:36.950 [https-openssl-apr-443-exec-5] DEBUG Transaction End : 
2019-01-08_00:08:23.678 [https-openssl-apr-443-exec-7] DEBUG Transaction Start : 
2019-01-08_00:08:23.787 [https-openssl-apr-443-exec-7] INFO  successfuly saved request[ref-17271929] of message type [pre].
2019-01-08_00:08:23.943 [https-openssl-apr-443-exec-7] DEBUG Transaction End : 
2019-01-08_00:08:39.537 [https-openssl-apr-443-exec-14] DEBUG Transaction Start : 
2019-01-08_00:08:39.646 [https-openssl-apr-443-exec-14] INFO  successfuly saved request[ref-17271930] of message type [setup].
2019-01-08_00:08:39.724 [https-openssl-apr-443-exec-14] DEBUG Transaction End : 
2019-01-08_00:08:55.896 [https-openssl-apr-443-exec-10] DEBUG Transaction Start : 
2019-01-08_00:08:55.896 [https-openssl-apr-443-exec-10] INFO  successfuly saved request[ref-17271931] of message type [LIVE].
2019-01-08_00:08:55.974 [https-openssl-apr-443-exec-10] DEBUG Transaction End : 
2019-01-08_00:09:35.178 [https-openssl-apr-443-exec-5] DEBUG Transaction Start : 
2019-01-08_00:09:35.303 [https-openssl-apr-443-exec-5] INFO  successfuly saved request[ref-17271932] of message type [setup].
2019-01-08_00:09:35.365 [https-openssl-apr-443-exec-5] DEBUG Transaction End : 
2019-01-08_00:09:40.784 [https-openssl-apr-443-exec-15] DEBUG Transaction Start : 
2019-01-08_00:09:40.799 [https-openssl-apr-443-exec-15] INFO  successfuly saved request[ref-17271935] of message type [query].
2019-01-08_00:09:40.846 [https-openssl-apr-443-exec-15] DEBUG Transaction End : 

[renjith_nair · Accepted solution]

@nareshinsvu ,

Give this a try

Updated:

Using transaction

index=* sourcetype=nareshinsvu
 |rex field=_raw "\[(?<Identifier>https-openssl-apr-443-exec-\d+)\]"
 |rex field=_raw "request\[(?<Request>ref-\d+)\]"|rex field=_raw "message type \[(?<Message>\w+)\]"
 |rex field=_raw "Transaction\s(?<Status>\w+)\s:"
 |transaction Identifier startswith="Transaction Start" endswith="DEBUG Transaction End"|eval endtime=_time+duration
 |eval StartTime=strftime(_time,"%Y-%m-%d %H:%M:%S"), EndTime=strftime(endtime,"%Y-%m-%d %H:%M:%S")
 |table StartTime,EndTime,Request,Message

--
"your base search"
|rex field=_raw "[(?https-openssl-apr-443-exec-\d+)]"
|rex field=_raw "request[(?ref-\d+)]"|rex field=_raw "message type [(?\w+)]"
|rex field=_raw "Transaction\s(?\w+)\s:"
|table _time,Identifier,Request,Message,Status|sort _time
|streamstats last(Identifier) as _prev current=f window=1
|eval sno=if(Identifier==_prev,0,1)| accum sno|eventstats values(Request) as Request by sno
|stats latest(eval(if(Status=="Start",_time,null()))) as Start,latest(eval(if(Status=="End",_time,null()))) as End,
values(Message) as Message by Identifier,Request

Please adjust the regex according to your requirement.

[nareshinsvu]

• I tried to explore each sub-command. Found attached results (below link) not matching the requirement. Sorry to bother with my complex requirement.

https://drive.google.com/file/d/1YlMa70PYUY_BjFSl7J1tyYH_Ikj5hjJU/view?usp=sharing

1)If a new request is initiated before completion of previous request, the formula fails "eventstats values(Request) as Request by sno"
2)If 2 requests are initiated on same identifier, the formula fails. "eventstats values(Request) as Request by sno"

Your time and help is very much appreciated

Thanks,
Naresh

[nareshinsvu]

And may be can we ask the query to check until the status is End in below query?

eval sno=if(Identifier==_prev,0,1)

[renjith_nair]

@nareshinsvu , since your events are not in order and there are duplication of identifiers, try with transaction

index=* sourcetype=nareshinsvu
 |rex field=_raw "\[(?<Identifier>https-openssl-apr-443-exec-\d+)\]"
 |rex field=_raw "request\[(?<Request>ref-\d+)\]"|rex field=_raw "message type \[(?<Message>\w+)\]"
 |rex field=_raw "Transaction\s(?<Status>\w+)\s:"
 |transaction Identifier startswith="Transaction Start" endswith="DEBUG Transaction End"|eval endtime=_time+duration
 |eval StartTime=strftime(_time,"%Y-%m-%d %H:%M:%S"), EndTime=strftime(endtime,"%Y-%m-%d %H:%M:%S")
 |table StartTime,EndTime,Request,Message

[nareshinsvu]

Hi Renjith - Got into inconsistent timed data issues. My output of _time does not match with the actual transaction time.

Is there a way to define StartTime and EndTime using a custom time extracted from _raw ?

Thanks,
Naresh

[nareshinsvu]

Worked perfect. Absolute Genius you are @renjith.nair

Can you throw some light on which one to use between UF and HF for this scenario? Some of the splunk pages say HF uses more resources. So, I didn't opt that for my previous use cases.

Since this looked complex when I started the work, thought of using HF. But you made it a smooch cake cut with just a single query.
If HF yields better results performance wise, can you please help me settingup my props.conf and transforms.conf for this example? Any other confs to be edited? Hope, All these conf changes should happen on the Indexer end - where the data is being sent to?

Thanks,
Naresh

[renjith_nair]

@nareshinsvu ,ok if it works, please accept it as answer 🙂 . I dont really get the question about the HF & UF. Do you want these extractions happening with configuration files ? If thats the case , one of the best approach is to correct the data at the source

[nareshinsvu]

Yes Renjith - My question is about Heavy Forwarder vs Universal Forwarder with the help of props.conf and transforms.conf.

[renjith_nair]

Ok. UF does not have much options for the transformations. So you have to do it either in HF or in indexer. However, it's purely based on the amount of data and performance. Please have a look at https://docs.splunk.com/Documentation/Splunk/7.2.3/Indexer/Indextimeversussearchtime .

Also for the search time extraction see - https://docs.splunk.com/Documentation/Splunk/7.2.3/Knowledge/Aboutfields

[nareshinsvu]

Hi @renjith.nair ,

Thanks for your response. But it's not completely working for me. It nullified the _time when I ran this. So, I created a table/datamodel until "|rex field=_raw "Transaction\s(?\w+)\s:" " from your query.and then able to only go until "sort _time". When I appended the next part of the query, Start and End came out as NULL. Am I missing something here?

The commands streamstats and accum are completely new to me. So, couldn't even able to understand it completely.

_time Identifier Request Message Status
2019-01-09 11:00:10 https-openssl-apr-443-exec-16 Start
2019-01-09 11:00:10 https-openssl-apr-443-exec-16 ref-17272845 setup

2019-01-09 11:00:10 https-openssl-apr-443-exec-16 End
2019-01-09 11:02:27 https-openssl-apr-443-exec-36 Start
2019-01-09 11:02:27 https-openssl-apr-443-exec-36 ref-17272846 setup

2019-01-09 11:02:27 https-openssl-apr-443-exec-36 End
2019-01-09 11:03:03 https-openssl-apr-443-exec-8 Start
2019-01-09 11:03:03 https-openssl-apr-443-exec-8 ref-17272847 saved
2019-01-09 11:03:05 https-openssl-apr-443-exec-8 End
2019-01-09 11:03:46 https-openssl-apr-443-exec-16 Start
2019-01-09 11:03:46 https-openssl-apr-443-exec-16 ref-17272848 pre

2019-01-09 11:03:46 https-openssl-apr-443-exec-16 End