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

[penningl]

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.

[penningl]

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

Hi @penningl

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

[strive]

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.

[penningl]

I have added extra information above to help explain better.

[strive]

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

[penningl]

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.

[strive]

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