Splunk Search

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


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


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


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.

New Member

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

0 Karma


thanks wpreston!

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

0 Karma


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


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
Get Updates on the Splunk Community!

.conf24 | Day 0

Hello Splunk Community! My name is Chris, and I'm based in Canberra, Australia's capital, and I travelled for ...

Enhance Security Visibility with Splunk Enterprise Security 7.1 through Threat ...

(view in My Videos)Struggling with alert fatigue, lack of context, and prioritization around security ...

Troubleshooting the OpenTelemetry Collector

  In this tech talk, you’ll learn how to troubleshoot the OpenTelemetry collector - from checking the ...