Measure time between two log events

[Petri-X]

Hi,

I have an SBC (Session Board Controller) which is doing LDAP search and write the syslog of that. I'm trying to get statistics of how long time the searches has been taken during the day.

Based on the forums discussions I end to the following search string already:

"recv <-- acEV_LDAP_SEARCH_RESULT" OR "send --> LDAP SearchID" | transaction SID | table by duration

So this is good and working. The extra challenge comes, when I'm not interest of all the LDAP searches only those which do have certain search (contains phone number).

I tried to change the search like this:

"recv <-- acEV_LDAP_SEARCH_RESULT" OR "send --> LDAP SearchID:-100 key:msRTCSIP-Line=tel:+" | transaction SID keeporphans=false  | table by duration

With the idea that if there is no pair for "recv <-- acEV_LDAP_SEARCH_RESULT", then that should be skipped. But so far, no luck 😞

And alternative way I tried to use third log line as well by:

"recv <-- acEV_LDAP_SEARCH_RESULT" OR "send --> LDAP SearchID" OR "Query LDAP for msRTCSIP-Line=tel:+" | transaction SID | table by duration

But that did not work either to me.

The SID is the thread ID (or session ID) to unify each others.

Anybody have thoughts how this could be done? Can I control Transaction in a way that both (or three) log lines are mandatory?

[Petri-X]

Alright, I found one way to get those complete events out duration>0:

"recv <-- acEV_LDAP_SEARCH_RESULT" OR "send --> LDAP SearchID:-100 key:msRTCSIP-Line=tel:+" | transaction SID | where duration>0

But looks that I'm hitting to limit of maxopentxn: Splunk: Is there a limit on the number of events returned from the transaction? 

Question, how to go forward 😄

Can I ask transaction to waste those events which are not having complete event? I can see there is "maxevents", but why not having "minevents" as well.

Or can this be looped somehow? So that I do query one hour at time? And in that way keep the transaction size enough small?

[ITWhisperer]

Can you share some example (anonymised) events in a code block </>?

[Petri-X]

Yes of course:

This is the one which is not so interested:

2022-01-14T10:32:58.165723+00:00 SBC11 [SID=eea661:142:11998931] (N 46857865) (#1):Query LDAP response: Found [Time:14-01@11:32:56.504]
2022-01-14T10:32:58.165723+00:00 SBC11 [SID=eea661:142:11998931] (N 46857864) LDAP_RESPONSE_EV: (#0)NULL -> (#1)CallSetupRulesSession [Time:14-01@11:32:56.504]
2022-01-14T10:32:58.165606+00:00 SBC11 [SID=eea661:142:11998931] (N 46857863) recv <-- acEV_LDAP_SEARCH_RESULT SearchId:286 SearchResultStatus=0 [Time:14-01@11:32:56.504]
2022-01-14T10:32:58.163900+00:00 SBC11 [SID=eea661:142:11998931] (N 46857859) (#1):Call Setup Run Rule 0: Query LDAP for msRTCSIP-Line=tel:* [Time:14-01@11:32:56.500]
2022-01-14T10:32:58.163900+00:00 SBC11 [SID=eea661:142:11998931] (N 46857858) send --> LDAP SearchID:-100 key:msRTCSIP-Line=tel:* Group:2 [Time:14-01@11:32:56.500]

This one I would like to measure:

2022-01-14T11:17:58.521265+00:00 SBC11 [SID=83978f:126:8131843] (N 14995265) (#3):Query LDAP response: Found [Time:14-01@12:17:57.970]
2022-01-14T11:17:58.521147+00:00 SBC11 [SID=83978f:126:8131843] (N 14995264) LDAP_RESPONSE_EV: (#0)NULL -> (#3)CallSetupRulesSession [Time:14-01@12:17:57.970]
2022-01-14T11:17:58.521147+00:00 SBC11 [SID=83978f:126:8131843] (N 14995263) recv <-- acEV_LDAP_SEARCH_RESULT SearchId:87 SearchResultStatus=0 [Time:14-01@12:17:57.970]
2022-01-14T11:17:58.520674+00:00 SBC11 [SID=83978f:126:8131843] (N 14995258) (#3):Call Setup Run Rule 0: Query LDAP for msRTCSIP-Line=tel:+12345678* [Time:14-01@12:17:57.969]
2022-01-14T11:17:58.520674+00:00 SBC11 [SID=83978f:126:8131843] (N 14995257) send --> LDAP SearchID:-100 key:msRTCSIP-Line=tel:+12345678* Group:2 [Time:14-01@12:17:57.969]

[ITWhisperer]

Rather than using transaction, you could try using stats

| makeresults
| eval _raw="2022-01-14T10:32:58.165723+00:00 SBC11 [SID=eea661:142:11998931] (N 46857865) (#1):Query LDAP response: Found [Time:14-01@11:32:56.504]
2022-01-14T10:32:58.165723+00:00 SBC11 [SID=eea661:142:11998931] (N 46857864) LDAP_RESPONSE_EV: (#0)NULL -> (#1)CallSetupRulesSession [Time:14-01@11:32:56.504]
2022-01-14T10:32:58.165606+00:00 SBC11 [SID=eea661:142:11998931] (N 46857863) recv <-- acEV_LDAP_SEARCH_RESULT SearchId:286 SearchResultStatus=0 [Time:14-01@11:32:56.504]
2022-01-14T10:32:58.163900+00:00 SBC11 [SID=eea661:142:11998931] (N 46857859) (#1):Call Setup Run Rule 0: Query LDAP for msRTCSIP-Line=tel:* [Time:14-01@11:32:56.500]
2022-01-14T10:32:58.163900+00:00 SBC11 [SID=eea661:142:11998931] (N 46857858) send --> LDAP SearchID:-100 key:msRTCSIP-Line=tel:* Group:2 [Time:14-01@11:32:56.500]
2022-01-14T11:17:58.521265+00:00 SBC11 [SID=83978f:126:8131843] (N 14995265) (#3):Query LDAP response: Found [Time:14-01@12:17:57.970]
2022-01-14T11:17:58.521147+00:00 SBC11 [SID=83978f:126:8131843] (N 14995264) LDAP_RESPONSE_EV: (#0)NULL -> (#3)CallSetupRulesSession [Time:14-01@12:17:57.970]
2022-01-14T11:17:58.521147+00:00 SBC11 [SID=83978f:126:8131843] (N 14995263) recv <-- acEV_LDAP_SEARCH_RESULT SearchId:87 SearchResultStatus=0 [Time:14-01@12:17:57.970]
2022-01-14T11:17:58.520674+00:00 SBC11 [SID=83978f:126:8131843] (N 14995258) (#3):Call Setup Run Rule 0: Query LDAP for msRTCSIP-Line=tel:+12345678* [Time:14-01@12:17:57.969]
2022-01-14T11:17:58.520674+00:00 SBC11 [SID=83978f:126:8131843] (N 14995257) send --> LDAP SearchID:-100 key:msRTCSIP-Line=tel:+12345678* Group:2 [Time:14-01@12:17:57.969]"
| multikv noheader=t
| table _raw
| eval _time=strptime(_raw,"%FT%T.%6Q%:z")
| fieldformat _time=strftime(_time,"%F %T.%6Q%:z")
| rex "SID=(?<sid>[^\]]+)"
| rex "(?<eventtype>(send|recv))"
| rex "key:msRTCSIP-Line=tel:(?<tel>[^\*]*?)\*"
| eval tel=if(len(tel)>0,tel,null())
| eval sendtime=if(eventtype=="send",_time,null())
| eval recvtime=if(eventtype=="recv",_time,null())
| stats values(sendtime) as sendtime values(recvtime) as recvtime values(tel) as tel by sid
| where isnotnull(tel)
| eval duration=recvtime-sendtime
| eval duration=tostring(duration,"duration")