topic Re: transaction query providing wrong log events in splunk in Splunk Search

transaction query providing wrong log events in splunk

kanamarlapudive — Wed, 30 Sep 2020 03:11:54 GMT

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 Average_response_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

Re: transaction query providing wrong log events in splunk

kanamarlapudive — Fri, 06 Dec 2019 07:48:29 GMT

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.

Re: transaction query providing wrong log events in splunk

to4kawa — Fri, 06 Dec 2019 17:31:42 GMT

| 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.

Re: transaction query providing wrong log events in splunk

woodcock — Fri, 06 Dec 2019 20:13:05 GMT

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

Re: transaction query providing wrong log events in splunk

kanamarlapudive — Sat, 07 Dec 2019 18:46:28 GMT

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.

Re: transaction query providing wrong log events in splunk

arjunpkishore5 — Sun, 08 Dec 2019 04:57:03 GMT

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

Re: transaction query providing wrong log events in splunk

kanamarlapudive — Sun, 08 Dec 2019 10:36:36 GMT

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

Re: transaction query providing wrong log events in splunk

arjunpkishore5 — Sun, 08 Dec 2019 13:55:17 GMT

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

Re: transaction query providing wrong log events in splunk

kanamarlapudive — Sun, 08 Dec 2019 14:56:22 GMT

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.

Re: transaction query providing wrong log events in splunk

arjunpkishore5 — Sun, 08 Dec 2019 15:17:02 GMT

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>)

| 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.

Re: transaction query providing wrong log events in splunk

kanamarlapudive — Sun, 08 Dec 2019 15:50:01 GMT

Hi Arjun,
Thanks for quick reply, i am able to convert the timestamp.

The below event log is my sample raw data. if i give "security gate check" i am able to see the start time , if i give " Security gate check POST" it is not working. I am giving post because some other requests has PATCH to avoid that event logs.

"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

Re: transaction query providing wrong log events in splunk

kanamarlapudive — Sun, 08 Dec 2019 17:12:52 GMT

Hi Arjun,

Can you provide how to calculate count for the same criteria, which either start or end is not null ( i.e. Start and end consider as one event).

If you can provide the query for this it will be very helpful.

Re: transaction query providing wrong log events in splunk

arjunpkishore5 — Sun, 08 Dec 2019 18:06:14 GMT

That's simple

| 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
| search start=* AND end=*
| eval duration = end-start
| stats avg(duration) as Average_Response_Time, count as total

Re: transaction query providing wrong log events in splunk

arjunpkishore5 — Sun, 08 Dec 2019 18:08:04 GMT

Also, if you need only POST events, add the filter to the base search like this

index= <your index> POST

OR if you need everything except PATCH

index=<your index> NOT PATCH

Re: transaction query providing wrong log events in splunk

arjunpkishore5 — Sun, 08 Dec 2019 18:08:09 GMT

Also, if you need only POST events, add the filter to the base search like this

index= <your index> POST

OR if you need everything except PATCH

index=<your index> NOT PATCH

Re: transaction query providing wrong log events in splunk

kanamarlapudive — Sun, 08 Dec 2019 18:09:50 GMT

Hi Arjun,

I did this , but i am getting null values of start and end of trace also including in this count, which i am looking to include both start and end not null case count.

Re: transaction query providing wrong log events in splunk

kanamarlapudive — Sun, 08 Dec 2019 18:13:32 GMT

Hi Arjun,

POST is not available in both events, it is available in start event only. I can't add this to base search.

Re: transaction query providing wrong log events in splunk

arjunpkishore5 — Sun, 08 Dec 2019 18:22:24 GMT

Hmm.

Are you getting duration values for events where start or end is null? If not, do this.

 | 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 | search duration=*
 | stats avg(duration) as Average_Response_Time, count as total

Re: transaction query providing wrong log events in splunk

kanamarlapudive — Sun, 08 Dec 2019 19:25:38 GMT

Hi Arjun,

Thank you for your patience for answering my questions.

I have two below queries, can you please suggest how to merge and get difference of counts in separate column.

index=A | rex field=_raw command=(?\w+) | stats count by CountA

index=A | rex field=_raw command=(?\w+) | stats count by CountB

Common ID i am getting through rex command.

I am looking for the below output,

Common ID Count A Count B Difference ( i.e. Count A - Count B)

Kindly suggest on this any approach, i have tried subsearch and joins. Unable to get the result.

Re: transaction query providing wrong log events in splunk

woodcock — Sun, 08 Dec 2019 21:32:19 GMT

You have Accepted this answer and closed it; was that a mistake? Do you have a working answer or do you still need help? There is an UnAccept button...