How to pull stats to display etime, bind_id, conn, and the search_filter for any operation that takes longer than 20 seconds

[justinsplunk_12]

Hi all,
I'm working with a sample log snippet below.

The overall goal is to get stats about long-running operations. I am trying to display the etime, bind_id, conn, and the search_filter for any operation that takes longer than 20 seconds (etime>20).

I've tried using "transaction" with conn but I do not know how to manipulate the data afterwards.

I am trying to get an output that looks similar to,

conn         bind_id               search_filter    etime
65110583     "uid=hello,o=test"    "(uid=abc*)"     165

::Log snippet::

2019-10-15T08:20:06+00:00 serverABC ACCESSLOG[15/Oct/2019]: 04:20:05 -0400] conn=65110583 op=-1 msgId=-1 -  connection from 10.10.10.10:1234 to 10.10.10.15
2019-10-15T08:20:06+00:00 serverABC ACCESSLOG[15/Oct/2019]: 04:20:05 -0400] conn=65110583 op=0 msgId=1 - BIND dn="uid=hello,o=test"
2019-10-15T08:20:06+00:00 serverABC ACCESSLOG[15/Oct/2019]: 04:20:05 -0400] conn=65110583 op=0 msgId=1 - RESULT err=0 tag=97 nentries=0 etime=0 dn="uid=hello,o=test"
2019-10-15T08:20:06+00:00 serverABC ACCESSLOG[15/Oct/2019]: 04:20:06 -0400] conn=65110583 op=1 msgId=2 - SRCH base="ou=everyone,o=test" scope=2 filter="(uid=abc*)" attrs="cn"
2019-10-15T08:20:10+00:00 serverABC ACCESSLOG[15/Oct/2019]: 04:20:08 -0400] conn=65110583 op=1 msgId=2 -  SORT uid (269746)
2019-10-15T08:23:01+00:00 serverABC ACCESSLOG[15/Oct/2019]: 04:22:51 -0400] conn=65110583 op=1 msgId=2 - RESULT err=0 tag=101 nentries=269746 etime=165 notes=U
2019-10-15T08:28:42+00:00 serverABC ACCESSLOG[15/Oct/2019]: 04:28:34 -0400] conn=65110583 op=2 msgId=3 - UNBIND
2019-10-15T08:28:42+00:00 serverABC ACCESSLOG[15/Oct/2019]: 04:28:34 -0400] conn=65110583 op=2 msgId=-1 - closing from 10.10.10.10:1234 - U1 - Connection closed by unbind client -

Thank you.

[mayurr98 · Accepted solution]

try this :

index=<your_index> 
| rex "dn=\"(?<bind_id>[^\"]+)" 
| rex "conn=(?<conn>\d+)" 
| rex "filter=\"\((?<search_filter>[^\)]+)" 
| rex "etime=(?<etime>\d+)" 
| stats values(bind_id) as bind_id max(etime) as etime_max values(search_filter) as search_filter by conn 
|  where etime_max > 20

If all the required fields are already extracted then don't use the rex expressions.

[justinsplunk_12]

thank you @mayurr98. this worked for most of the connections. Others have multiple searches in one connection start to end and so I find i need to group by conn and msgId. Im just trying to figure out how to now associate bind_id with the conn. I was thinking maybe some sort of subsearch, appendcols, or join ? Not sure.
For example:

index=xyz host=serverABC
| rex "BIND dn=(?.)\smethod"
| rex "filter=(?.)\sattrs"
| stats values(bind_id) as bind_id max(etime) as etime_max values(search_filter) as search_filter by conn msgId
| where etime_max > 20

output:
conn msgId bind_id etime_max search_filter
11001119 3 22 "(uid=abc*)"
11001119 2 25 "(uid=123*)"

2019-11-05T07:24:27+00:00 serverABC ACCESSLOG[05/Nov/2019]: 02:24:24 -0500] conn=11001119 op=0 msgId=1 - BIND dn="uid=hello,o=test"
2019-11-05T07:24:27+00:00 serverABC ACCESSLOG[05/Nov/2019]: 02:24:24 -0500] conn=11001119 op=0 msgId=1 - RESULT err=0 tag=97 nentries=0 etime=0 "uid=hello,o=test"
2019-11-05T07:24:27+00:00 serverABC ACCESSLOG[05/Nov/2019]: 02:24:24 -0500] conn=11001119 op=1 msgId=2 - SRCH base="ou=none,o=test" scope=2 filter="(uid=xyz*)" attrs="cn"
2019-11-05T07:24:27+00:00 serverABC ACCESSLOG[05/Nov/2019]: 02:24:24 -0500] conn=11001119 op=1 msgId=2 - RESULT err=0 tag=101 nentries=1 etime=25
2019-11-05T07:24:27+00:00 serverABC ACCESSLOG[05/Nov/2019]: 02:24:24 -0500] conn=11001119 op=2 msgId=3 - SRCH base="ou=everyone,o=test" scope=2 filter="(uid=abc*)" attrs="cn"
2019-11-05T07:24:38+00:00 serverABC ACCESSLOG[05/Nov/2019]: 02:24:28 -0500] conn=11001119 op=2 msgId=3 - RESULT err=0 tag=101 nentries=7187 etime=22

[mayurr98]

how does your output look like in this case?

[justinsplunk_12]

Sorry theres some weird formatting for the splunk search i replied with. The bind_id is blank but everything else is correct.

The output is like this:
conn msgId bind_id etime_max search_filter
11001119 3 22 "(uid=abc*)"
11001119 2 25 "(uid=123*)"

Desired output:
conn msgId bind_id etime_max search_filter
11001119 3 "uid=hello,o=test" 22 "(uid=abc*)"
11001119 2 "uid=hello,o=test" 25 "(uid=123*)"

[mayurr98]

add this after stats command:

| eventstats values(bind_id) as bind_id by conn  
|  where etime_max > 20

[justinsplunk_12]

ahh, it works and it looks so simple. I guess i was making it harder than it needed to be with trying to use transaction etc. thank you!

[woodcock]

Like this:

index="YouShouldAlwaysSpecifyAnIndex" AND sourcetype="AndSourcetypeToo"
| stats range(_time) AS duration max(etime) AS etime_max sum(etime) AS etime_total BY conn bind_id search_filter
| fieldformat duration=tostring(duration, "duration")
| fieldformat etime_max=tostring(etime_max, "duration")
| fieldformat etime_total=tostring(etime_total, "duration")