Splunk Search

Measure time between two log events

Petri-X
Explorer

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?

Labels (1)
Tags (2)
0 Karma

Petri-X
Explorer

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 maxopentxnSplunk: 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?

 

0 Karma

ITWhisperer
SplunkTrust
SplunkTrust

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

0 Karma

Petri-X
Explorer

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]

 

0 Karma

ITWhisperer
SplunkTrust
SplunkTrust

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")
0 Karma
Get Updates on the Splunk Community!

How I Instrumented a Rust Application Without Knowing Rust

As a technical writer, I often have to edit or create code snippets for Splunk's distributions of ...

Splunk Community Platform Survey

Hey Splunk Community, Starting today, the community platform may prompt you to participate in a survey. The ...

Observability Highlights | November 2022 Newsletter

 November 2022Observability CloudEnd Of Support Extension for SignalFx Smart AgentSplunk is extending the End ...