topic Re: If there are multiple events that start a transaction, how to write a transaction search to find the earliest one? in Splunk Search

If there are multiple events that start a transaction, how to write a transaction search to find the earliest one?

czervos — Tue, 21 Oct 2014 17:55:46 GMT

Let's say I have a log that containts

starttranscation
some other events
end transaction
some other events
starttransaction
starttransaction <--- note this is not a typo it is indeed a legit second starttransaction event
some other events
end transaction

We want for the first transaction to be delineated by event 1 to 3 and the second transaction to be delineated by event 5 to 8.

If we use (transaction startswith="starttransaction" endswith="end transaction" my second transaction is delineated by events 6 to 8 instead of 5-8. As a result the duration is shorter than what expected. In other words the starttransaction event proceeding the end transaction event is always being picked whereas we would like for the first "starttransaction" following the end transaction to be picked.

Re: If there are multiple events that start a transaction, how to write a transaction search to find the earliest one?

martin_mueller — Tue, 21 Oct 2014 20:04:48 GMT

I believe this search illustrates your question:

| stats count | eval event = "end start start" | makemv event | mvexpand event | streamstats count | eval _time = now() - count | transaction startswith="event=start" endswith="event=end" keepevicted=t

Returns one two-event transaction and one left over "start" event.

Re: If there are multiple events that start a transaction, how to write a transaction search to find the earliest one?

czervos — Wed, 29 Oct 2014 19:50:53 GMT

Thank you for your reply Martin perhaps I oversimplified the example here in that the first transaction had a sing start event and the second had two identical start event. The reality is that I have many transactions and each transaction can have one, two or many start events. Tried your suggestion but it did not help.

Re: If there are multiple events that start a transaction, how to write a transaction search to find the earliest one?

wpreston — Wed, 29 Oct 2014 20:49:27 GMT

I think you can do this using streamstats to count each occurrence of your starting events, using eventstats to find the starting event with the highest count (i.e., the oldest one), and then include that count as a criteria for startswith.

For my example search, assume that gField is the field that contains the common element between your events (like a transaction number, session id, or something like that), and that sField is a field that you use in your startswith criteria

... your base search ... | streamstats count by gField sField | eventstats max(count) as sFieldMax by sField | transaction gField startswith="sField=<starting value> count=sFieldOrder" endswith="sField=<ending value>"

Modifying the illustration by @martin_mueller the search would look like this:

| stats count | eval event = "end start start" | makemv event | mvexpand event | eval sField=1 | streamstats count | eval _time = now() - count | eventstats max(count) as mCount by sField | transaction startswith="event=start sField=mCount" endswith="event=end" keepevicted=t

Someone else out there may have a more streamlined approach, but this should do the trick for you.

Re: If there are multiple events that start a transaction, how to write a transaction search to find the earliest one?

czervos — Mon, 28 Sep 2020 17:58:19 GMT

Thank you Martin, unfortuantely I do not have a common element between the events in my transactions. I am trying to measure how long it takes for wpa_supplicant to connect to an AP after it starts scanning. Often it scans for more than once before it connects and as a result many scan-started events are recorded. My reduced data set is something like this

1412026262.159449: wlan2: CTRL-EVENT-SCAN-STARTED <---- start of transaction 1
1412026258.783734: wlan2: CTRL-EVENT-SCAN-STARTED
1412026226.229726: wlan2: CTRL-EVENT-SCAN-STARTED
1412026211.712098: wlan2: CTRL-EVENT-SCAN-STARTED
1412026203.900786: wlan2: CTRL-EVENT-CONNECTED - Connection to e8:ed:f3:10:cd:3f completed [id=0 id_str=] <--- end of transaction 1
1412026188.747661: wlan2: CTRL-EVENT-SCAN-STARTED <---- start of transaction 2
1412026177.658687: wlan2: CTRL-EVENT-SCAN-STARTED
1412026147.650857: wlan2: CTRL-EVENT-CONNECTED - Connection to e8:ed:f3:10:51:2f completed [id=0 id_str=] <--- end of transaction 2
1412026146.463960: wlan2: CTRL-EVENT-SCAN-STARTED <---- start of transaction 3
1412026143.323471: wlan2: CTRL-EVENT-SCAN-STARTED
1412026131.259936: wlan2: CTRL-EVENT-SCAN-STARTED
1412026125.254478: wlan2: CTRL-EVENT-SCAN-STARTED
1412026110.808932: wlan2: CTRL-EVENT-CONNECTED - Connection to e8:ed:f3:10:6e:ff completed [id=0 id_str=] <--- end of transaction 3
1412026109.575031: wlan2: CTRL-EVENT-SCAN-STARTED
1412026105.132968: wlan2: CTRL-EVENT-SCAN-STARTED
1412026089.933802: wlan2: CTRL-EVENT-CONNECTED - Connection to f8:4f:57:66:53:9f completed [id=0 id_str=]
1412026087.472444: wlan2: CTRL-EVENT-SCAN-STARTED
1412026073.058930: wlan2: CTRL-EVENT-SCAN-STARTED
1412026050.153576: wlan2: CTRL-EVENT-CONNECTED - Connection to e8:ed:f3:10:cd:3f completed [id=0 id_str=]

As you see more often than not there are more than one scans before the supplicant connects (the transaction ends)

If I make my transaction to be

| transaction startswith="CTRL-EVENT-SCAN-STARTED" endswith="CTRL-EVENT-CONNECTED"

then instead of picking the first scan-started event in each transaction it picks up the last scan-started in each transaction and as a result duration of my transactions is much shorter than what I really am interested in measuring.

Re: If there are multiple events that start a transaction, how to write a transaction search to find the earliest one?

stanwin — Mon, 01 Aug 2016 13:19:17 GMT

thanks wpreston!

This works! perhaps a flag to consider the earliest startswith event as feature enhancement might be good..

Re: If there are multiple events that start a transaction, how to write a transaction search to find the earliest one?

ohmyguigs — Mon, 06 Mar 2017 15:45:46 GMT

Where did sFieldOrder came from? (in the first example)