Splunk Search
Highlighted

transaction query providing wrong log events in splunk

New Member

Hi team,

I have two log events as mentioned below, i am trying to find out response time difference based on timestamp in both events
duration using unique trace.

|rex field=raw "(?[\w+,\w+,\w+])" | transaction trace startswith="Security gate check " endswith="found valid consumer for Identity" | stats avg(duration) as Averageresponse_Time

Here i am using trace in transaction. My question is in both log events trace should be same, but here it is not picking like that.

output log events

1st one :

2019-12-05 08:03:25.348 INFO [price:promotion:rrt-0c8dfd466053d7c3c-b-de-18025-17252943-6,4c5c49909b36f6f3,4c5c49909b36f6f3] 23 xxxxx : Security gate check : requestURI : /promotions/async : HttpMethod : POST
2019-12-05 08:03:26.965 INFO [price:promotion:rrt-0c8dfd466053d7c3c-b-de-18025-17252943-6,4c5c49909b36f6f3,4c5c49909b36f6f3] 23 --- : MSG=found valid consumer for Identity

Wrong output event :

2019-12-05 05:56:43.143 INFO [demo-23-01,bcc040a4340dd02e,bcc040a4340dd02e] 23 --- [qtp700631078-191] c.t.a.p.a.s.u.SecurityContextRepository : Security gate check : requestURI : /promotions/async : HttpMethod : POST
2019-12-05 05:57:36.967 INFO [testTraceId,a4d364b8545e7228,4d099a62c112f025] 23 --- : MSG=found valid consumer for Identity

in transaction why log events are not picking based on trace. Kindly suggest any changes required in my query.

Regards,
Vinay

0 Karma
Highlighted

Re: transaction query providing wrong log events in splunk

New Member

Hi team,

I am looking for in the given splunk query, if start event is available and end event is not avaialble it should not pick the wrong event as a end event. In such cases it should not consider it as a successful transaction, i would like to showcase it as a failed transaction or incomplete transaction.

How can we achieve the expected result, kindly suggest on the same.

0 Karma
Highlighted

Re: transaction query providing wrong log events in splunk

Ultra Champion
| makeresults 
| eval raw="2019-12-05 08:03:25.348 INFO [price:promotion:rrt-0c8dfd466053d7c3c-b-de-18025-17252943-6,4c5c49909b36f6f3,4c5c49909b36f6f3] 23 xxxxx : Security gate check : requestURI : /promotions/async : HttpMethod : POST
2019-12-05 08:03:26.965 INFO [price:promotion:rrt-0c8dfd466053d7c3c-b-de-18025-17252943-6,4c5c49909b36f6f3,4c5c49909b36f6f3] 23 --- : MSG=found valid consumer for Identity" 
| append
    [|makeresults | eval raw="2019-12-05 05:56:43.143 INFO [demo-23-01,bcc040a4340dd02e,bcc040a4340dd02e] 23 --- [qtp700631078-191] c.t.a.p.a.s.u.SecurityContextRepository : Security gate check : requestURI : /promotions/async : HttpMethod : POST
2019-12-05 05:57:36.967 INFO [testTraceId,a4d364b8545e7228,4d099a62c112f025] 23 --- : MSG=found valid consumer for Identity"]
| makemv delim="
" raw
| mvexpand raw
| rex field=raw "^(?<time>\d+\-\d+\-\d+ \d+:\d+:\d+\.\d+)"
| eval _time = strptime(time,"%F %T.%3Q")
| rename raw as _raw
| rex  "\[(?<id>[^\]]+)\]"
| table _time _raw id
| rename COMMENT AS "this is sample data, logic is below"
| eventstats range(eval(if(searchmatch("Security gate check") OR searchmatch("found"),_time,NULL))) as duration by id
| convert dur2sec(duration)

Hi, @kanamarlapudivenkatanagavinaykumar
transaction is unnecessary.

0 Karma
Highlighted

Re: transaction query providing wrong log events in splunk

Esteemed Legend

Never use transaction; try this:

Your Search Here
|rex field=_raw "(?[\w+,\w+,\w+])" 
| streamstats count(searchmatch("found valid consumer for Identity")) AS sessionID
| stats range(_time) AS duration BY sessionID
| stats avg(duration) as Average_response_Time
0 Karma
Highlighted

Re: transaction query providing wrong log events in splunk

New Member

Hi Woodcock,
Thanks for your reply.

Both log events are from same request only, one is related to one layer and second one is related to another layer of same request. We are trying to find the each layer wise response time. in both statements only one common trace id is only available. the given query is not resulting any results.

Kindly provide alternative solution for my requirement.

0 Karma
Highlighted

Re: transaction query providing wrong log events in splunk

Motivator

Do you really need to use transaction? Wouldn't something like this do ?

| stats min(eval(if(match(_raw, "Security gate check"), _time, null()))) as start, max(eval(if(match(_raw, "found valid consumer for Identity"), _time, null()))) as end by trace
| eval duration = end-start
| stats avg(duration) as Average_Response_Time

View solution in original post

0 Karma
Highlighted

Re: transaction query providing wrong log events in splunk

New Member

Hi Arjun,
I am unable to receive with this query start time. Can you explain the query for understanding my requirement.

0 Karma
Highlighted

Re: transaction query providing wrong log events in splunk

Motivator

Hi @kanamarlapudivenkatanagavinaykumar

2 probabilities here.
1. The selected time range is not large enough to cover the whole event. Try increasing the time range.
2. There is a difference in case. For this, modify the query as below.

 | stats min(eval(if(match(lower(_raw), "security gate check"), _time, null()))) as start, max(eval(if(match(lower(_raw), "found valid consumer for identity"), _time, null()))) as end by trace
 | eval duration = end-start
 | stats avg(duration) as Average_Response_Time

What I'm doing here is, I'm taking the min start time for events which have the phrase "security gate check" as the start time, and max time of events which have the phrase "found valid consumer for identity" as the end time per trace. The assumption is trace is unique per transaction.

Hope this helps

0 Karma
Highlighted

Re: transaction query providing wrong log events in splunk

New Member

hi Arjun,

Thanks for quick reply.

Even the events available in the selected time range ( i.e 7 days), I am getting as a null for start time. For end time i am able to see end time in Unix timestamp format. How to get the actual timestamp instead of unix epoch format.

Kindly suggest on the same.

0 Karma
Highlighted

Re: transaction query providing wrong log events in splunk

Motivator

That's very strange that you are getting just the end and not the start time. It looks like it's unable to find the pattern "Security gate check" in _raw. Could you verify that there are no special characters in the raw events?

Another possibility is that it's unable to find start and end events for the same trace. Try sorting by start to see if you events with start but no end. In that case, the regex for extracting the trace might need to be modified.

To convert epoch to standard time, you can use one of the following

| convert ctime(<your time field>)

OR

| eval <time field> = strftime(<time field>, "<desired time format>") 

Use this to build the time format string - https://docs.splunk.com/Documentation/Splunk/8.0.0/SearchReference/Commontimeformatvariables

Please upvote if this helped you.

0 Karma