Splunk Search

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

czervos
Explorer

Let's say I have a log that containts

  1. starttranscation
  2. some other events
  3. end transaction
  4. some other events
  5. starttransaction
  6. starttransaction <--- note this is not a typo it is indeed a legit second starttransaction event
  7. some other events
  8. 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.

0 Karma

czervos
Explorer

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.

0 Karma

wpreston
Motivator

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.

ohmyguigs
New Member

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

0 Karma

stanwin
Contributor

thanks wpreston!

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

0 Karma

czervos
Explorer

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.

0 Karma

martin_mueller
SplunkTrust
SplunkTrust

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.

0 Karma
.conf21 Now Fully Virtual!
Register for FREE Today!

We've made .conf21 totally virtual and totally FREE! Our completely online experience will run from 10/19 through 10/20 with some additional events, too!