Splunk Search

How to search transaction events to accurately calculate session/conference duration?

penningl
Explorer

Trying to find a way to "transaction" the data like below. However because of the way the data flows we are essentially getting duplicate transactions for what should be the same transaction. I will try and explain:

Sep 2 11:50:30 10.128.110.38 Sep 2 10:50:30.330 eurblah03 2014-09-02 10:50:30,330 Level="INFO" Name="administrator.conference" Message="Conference has been stopped." Conference="Test Conference (VMR)"
Sep 2 09:29:26 10.42.200.60 Sep 2 08:29:26.306 ausblah04 2014-09-02 08:29:26,305 Level="INFO" Name="administrator.conference" Message="Conference has been stopped." Conference="Test Conference (VMR)"
Sep 2 08:37:34 10.128.110.38 Sep 2 07:37:34.890 eurblah03 2014-09-02 07:37:34,890 Level="INFO" Name="administrator.conference" Message="Conference has been created." Conference="Test Conference (VMR)"
Sep 2 08:36:53 10.42.200.60 Sep 2 07:36:53.084 ausblah04 2014-09-02 07:36:53,084 Level="INFO" Name="administrator.conference" Message="Conference has been created." Conference="Test Conference (VMR)"
Sep 2 08:36:31 10.42.200.14 Sep 2 07:36:30.941 ausblah03 2014-09-02 07:36:30,941 Level="INFO" Name="administrator.conference" Message="Conference has been stopped." Conference="Test Conference (VMR)"
Sep 2 08:33:19 10.42.200.14 Sep 2 07:33:19.252 ausblah03 2014-09-02 07:33:19,251 Level="INFO" Name="administrator.conference" Message="Conference has been created." Conference="Test Conference (VMR)"
Sep 2 08:33:10 10.42.200.14 Sep 2 07:33:10.062 ausblah03 2014-09-02 07:33:10,062 Level="INFO" Name="administrator.conference" Message="Conference has been stopped." Conference="Test Conference (VMR)"
Sep 2 08:30:12 10.42.200.14 Sep 2 07:30:11.992 ausblah03 2014-09-02 07:30:11,992 Level="INFO" Name="administrator.conference" Message="Conference has been created." Conference="Test Conference (VMR)"

We have conference data from syslogs . A conference always has a conference name,
e.g. Conference="Test Conference (VMR)"
and when it starts and stops,
message=Conference has been created" and "Conference has been stopped".

However, a conference can be started from one server e.g. Australia : ausblah04, yet participants from Europe would be dialled into exactly the same conference from another server e.g Europe : eurblah03. Those two servers then effectively talk to each other.

4th event from top (08:36:53) is when a conference is started from server ausblah04. The next event up shows the same conference is being started from a different server, eurblah03. They are the same conference. When you transaction the events by Conference field, you would get two transactions for the top 4 events,

Sep 2 08:37:34 10.128.110.38 Sep 2 07:37:34.890 eurpexcn03 2014-09-02 07:37:34,890 Level="INFO" Name="administrator.conference" Message="Conference has been created." Conference="SYD Balmoral (VMR)" Service-type="conference"
Sep 2 09:29:26 10.42.200.60 Sep 2 08:29:26.306 auspexcn04 2014-09-02 08:29:26,305 Level="INFO" Name="administrator.conference" Message="Conference has been stopped." Conference="SYD Balmoral (VMR)" Duration="3153.116"

Sep 2 08:36:53 10.42.200.60 Sep 2 07:36:53.084 auspexcn04 2014-09-02 07:36:53,084 Level="INFO" Name="administrator.conference" Message="Conference has been created." Conference="SYD Balmoral (VMR)" Service-type="conference"
Sep 2 11:50:30 10.128.110.38 Sep 2 10:50:30.330 eurpexcn03 2014-09-02 10:50:30,330 Level="INFO" Name="administrator.conference" Message="Conference has been stopped." Conference="SYD Balmoral (VMR)" Duration="11575.335"

The actual conference started at the 4th event and ended at the 1st. When I start to do stats on the above to calculate total usage etc it will always be over what it should be as it will be adding "3153" + "11575" instead of just "11575".


UPDATE

OK, I think it will help if I add a bit more of the data to help explain.

Sep 2 11:50:30 10.128.110.38 Sep 2 10:50:30.330 eurblah03 2014-09-02 10:50:30,330 Level="INFO" Name="administrator.conference" Message="Conference has been stopped." Conference="Test Conference (VMR)" Duration="11575.335"
Sep 2 11:50:30 10.128.110.38 Sep 2 10:50:30.328 eurblah03 2014-09-02 10:50:30,328 Level="INFO" Name="administrator.conference" Message="Participant has disconnected." Conference="Test Conference (VMR)" Participant="sip:57253@eur.vc.blah.com" DisplayName="" Call-id="c84e60299ef3e761@10.132.130.12" Location="Europe" Duration="11571.402" Detail="Remote disconnect"
Sep 2 09:29:26 10.128.110.38 Sep 2 08:29:26.833 eurblah03 2014-09-02 08:29:26,833 Level="INFO" Name="administrator.conference" Message="Participant has disconnected." Conference="Test Conference (VMR)" Participant="backplane:10.42.200.60" DisplayName="" Call-id="6301fff8-36a8-4334-b6db-0115802c165c" Location="Europe" Duration="3104.197" Detail="Backplane disconnected"
Sep 2 09:29:26 10.42.200.60 Sep 2 08:29:26.770 ausblah04 2014-09-02 08:29:26,770 Level="INFO" Name="administrator.conference" Message="Participant has disconnected." Conference="Test Conference (VMR)" Participant="backplane:10.128.110.38" DisplayName="" Call-id="2cac00cf-5435-4f5f-95c7-855a6f87942c" Location="Australasia" Duration="3104.729" Detail="Backplane disconnected"
Sep 2 09:29:26 10.42.200.60 Sep 2 08:29:26.306 ausblah04 2014-09-02 08:29:26,305 Level="INFO" Name="administrator.conference" Message="Conference has been stopped." Conference="Test Conference (VMR)" Duration="3153.116"
Sep 2 09:29:26 10.42.200.60 Sep 2 08:29:26.305 ausblah04 2014-09-02 08:29:26,304 Level="INFO" Name="administrator.conference" Message="Participant has disconnected." Conference="Test Conference (VMR)" Participant="sip:48954@aus.vc.blah.com" DisplayName="Sydney-Palm" Call-id="a71ac6fbdf75752de12c65eed70ae91f" Location="Australasia" Duration="3151.313" Detail="Remote disconnect"
Sep 2 08:44:21 10.128.110.38 Sep 2 07:44:21.381 eurblah03 2014-09-02 07:44:21,381 Level="INFO" Name="administrator.conference" Message="Participant has stopped presenting." Conference="Test Conference (VMR)" Participant="sip:57253@eur.vc.blah.com" Call-id="c84e60299ef3e761@10.132.130.12"
Sep 2 08:44:19 10.128.110.38 Sep 2 07:44:19.243 eurblah03 2014-09-02 07:44:19,243 Level="INFO" Name="administrator.conference" Message="Participant is presenting." Conference="Test Conference (VMR)" Participant="sip:57253@eur.vc.blah.com" Call-id="c84e60299ef3e761@10.132.130.12"
Sep 2 08:37:42 10.128.110.38 Sep 2 07:37:42.601 eurblah03 2014-09-02 07:37:42,600 Level="INFO" Name="administrator.conference" Message="Participant has joined." Conference="Test Conference (VMR)" Participant="backplane:10.42.200.60" DisplayName="" Vendor="Unknown" Call-id="6301fff8-36a8-4334-b6db-0115802c165c" Location="Europe" Signaling-node="10.128.110.38" Media-node="10.128.110.38"
Sep 2 08:37:42 10.42.200.60 Sep 2 07:37:41.937 ausblah04 2014-09-02 07:37:41,937 Level="INFO" Name="administrator.conference" Message="Participant has joined." Conference="Test Conference (VMR)" Participant="backplane:10.128.110.38" DisplayName="" Vendor="Unknown" Call-id="2cac00cf-5435-4f5f-95c7-855a6f87942c" Location="Australasia" Signaling-node="10.42.200.60" Media-node="10.42.200.60"
Sep 2 08:37:38 10.128.110.38 Sep 2 07:37:38.821 eurblah03 2014-09-02 07:37:38,821 Level="INFO" Name="administrator.conference" Message="Participant has joined." Conference="Test Conference (VMR)" Participant="sip:57253@eur.vc.blah.com" DisplayName="" Vendor="TANDBERG/517 (TC5.1.8.303428)" Call-id="c84e60299ef3e761@10.132.130.12" Location="Europe" Signaling-node="10.128.110.178" Media-node="10.128.110.38"
Sep 2 08:37:34 10.128.110.38 Sep 2 07:37:34.890 eurblah03 2014-09-02 07:37:34,890 Level="INFO" Name="administrator.conference" Message="Conference has been created." Conference="Test Conference (VMR)" Service-type="conference"
Sep 2 08:36:55 10.42.200.60 Sep 2 07:36:54.886 ausblah04 2014-09-02 07:36:54,886 Level="INFO" Name="administrator.conference" Message="Participant has joined." Conference="Test Conference (VMR)" Participant="sip:48954@aus.vc.blah.com" DisplayName="Sydney-Palm" Vendor="TANDBERG/518 (TC6.2.0.20b1616)" Call-id="a71ac6fbdf75752de12c65eed70ae91f" Location="Australasia" Signaling-node="10.42.200.60" Media-node="10.42.200.60"
Sep 2 08:36:53 10.42.200.60 Sep 2 07:36:53.084 ausblah04 2014-09-02 07:36:53,084 Level="INFO" Name="administrator.conference" Message="Conference has been created." Conference="Test Conference (VMR)" Service-type="conference"

Basic flow goes in time order:

  • ausblah01 server - Test Conference created - Start Time of Conference Transaction
  • ausblah01 server - Participant Join - Total 1 participant is joined to conference
  • eurblah01 server - Test Conference created
  • eurblah01 server - Participant Join - Total 2 participants are joined to conference
  • ausblah01 server - Participant Join - Total 3 participants are joined to conference
  • eurblah01 server - Participant Join - Total 4 participants are joined to conference
  • ausblah01 server - Participant Leave - Total 3 participants are joined to conference
  • ausblah01 server - Participant Leave - Total 2 participants are joined to conference
  • ausblah01 server - Test Conference ends
  • eurblah01 server - Participant Leave - Total 1 participants are joined to conference
  • eurblah01 server - Participant Leave - Total 0 participants are joined to conference
  • eurblah01 server - Test Conference ends - End Time of Conference Transaction

The transaction command is picking up the intermediate Conference Start / End as is correct, but I don't want it to as it is technically only 1 Conference overall, so I want only 1 transaction to be the result. Notice you can start/end a conference from different servers, it is only when there are no participants attending that a conference ends.

0 Karma

penningl
Explorer

| transaction Conference startswith="Conference has been created" endswith="Conference has been stopped" mvlist=t | eval start_time=mvindex(_time, 0) | concurrency start=start_time duration=duration | where concurrency < 2

I think I may have found a solution from another post, http://answers.splunk.com/answers/106367/concurrent-sessions-with-start-and-stop-events-and-multiple...

It uses concurrency to find the overlapping transactions, then I can just filter them out after.

ppablo
Retired

Hi @penningl

Did this search (inspired by the post you referenced) solve your transaction issue?

0 Karma

strive
Influencer

Try Some thing like this

Your search terms... | eventstats min(Start_Time) as ActualStartTime, max(Duration) as ActualDuration by Conference | where Start_Time=ActualStartTime and Duration=ActualDuration

The Start_Time here is the time present in your log event (start time of conference). You have to convert it into epoch format before applying eventstats.

0 Karma

penningl
Explorer

I have added extra information above to help explain better.

0 Karma

strive
Influencer

So, your need is.. you just need one event for start and one event for end of the conference.

0 Karma

penningl
Explorer

Maybe transaction isn't the right command initially, the 1st transaction events are actually inside the timeframe of the 2nd transaction, so I want only the 2nd transaction to be there.

0 Karma

strive
Influencer

Transaction command is working properly. Are you trying to find out the duration of the conferences?

0 Karma
Get Updates on the Splunk Community!

Index This | I am a number, but when you add ‘G’ to me, I go away. What number am I?

March 2024 Edition Hayyy Splunk Education Enthusiasts and the Eternally Curious!  We’re back with another ...

What’s New in Splunk App for PCI Compliance 5.3.1?

The Splunk App for PCI Compliance allows customers to extend the power of their existing Splunk solution with ...

Extending Observability Content to Splunk Cloud

Register to join us !   In this Extending Observability Content to Splunk Cloud Tech Talk, you'll see how to ...