transaction query providing wrong log events in splunk

[kanamarlapudive]

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

[arjunpkishore5 · Accepted solution]

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

[kanamarlapudive]

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

[arjunpkishore5]

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

[kanamarlapudive]

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.

[arjunpkishore5]

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.

[kanamarlapudive]

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

[kanamarlapudive]

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.

[arjunpkishore5]

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

[kanamarlapudive]

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.

[kanamarlapudive]

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.

[arjunpkishore5]

Hi @kanamarlapudivenkatanagavinaykumar

It looks like some part of your query is missing. Once you enter query, highlight it and press the code sample button (The button with 1's and 0's) This will ensure that the everything within the code sample is retained.

Also, is this a different question from the original question in the post? If yes, could you please post this as a new question? This helps others who have a similar problem as you are. A new question in the comment kind of get's lost since other's wouldn't be able to view it and you miss out on inputs from other contributors in the forum 🙂

[woodcock]

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

[kanamarlapudive]

Hi Woodcock,
Arjun helped regarding this query, it is working fine. I am looking for another solution. Which i will raise as a separate request.

[arjunpkishore5]

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

[arjunpkishore5]

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

[kanamarlapudive]

Hi Arjun,

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

[arjunpkishore5]

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

[woodcock]

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

[kanamarlapudive]

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.

[to4kawa]

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