Splunk Search

Why is transaction not working when finding time between events?

algol2
Engager

I'm new to Splunk, so apologies if this is a silly question.

I have a log file that reads:

 

 

2023-03-22 00:57:09,517 INFO  TestScript - Generating reports with date of 20230321 and thread pool size of 5
...
...
2023-03-22 00:59:23,681 INFO  MultiTestScript - Multi Test report generation completed successfully!

 

 

 

and I am trying to extract the elapsed time between these two events.

If I try this search

 

 

<search terms> | transaction startswith="Generating reports" endswith="report generation completed"

 

 

 

I get no results found.

 

If I search for the two halves of the transaction separately, i.e.

 

 

<search terms> | transaction startswith="Generating reports"

 

 

and

 

 

<search terms> | transaction endswith="report generation completed"

 

 

the search returns the appropriate part of the log file.

As soon I combine the startswith= and endswith= fields in a single search, however, I get no results.

 

This query works properly with another log file. The only difference I can see between the files is that the file that works contains multiple transactions (i.e. "Generating report"/"report generation completed" pairs) while the files that won't work contain only one.

 

Labels (1)
Tags (1)
0 Karma
1 Solution

yeahnah
Motivator

The transaction command works best when there is a key field (e.g. correlation ID) shared between events that tie the events together.  In this case it can only go on time order, which, depending on what is logging the output, may not be a very reliable way to pair events.

It really comes down to what you are trying to achieve.  Is it just the total time between the first event (startswith) and the very last event (endswith)?  If so, then something like the stats command would be better and far more efficient...

 

search term ... ("Generating reports") OR ("report generation completed")
| eval type=if(searchmatch("Generating reports"), "startswith", "endswith")
| stats min(eval(if(type="startswith", _time, ""))) AS start
        max(eval(if(type="endswith", _time, ""))) AS end
| eval duration=end - start
      ,duration_hm=tostring(duration, "duration")
| foreach start end [ eval <<FIELD>>=strftime('<<FIELD>>', "%c") ]

 


It's important to be clear in what you are aiming to achieve.

Hope this helps
    

View solution in original post

yeahnah
Motivator

Hi @algol2 

That's a bit strange, for sure. 

Try adding the following parameters and see if that makes a difference...

| transaction maxevents=2 keepevicted=true keeporphans=true startswith="Generating reports" endswith="report generation completed" 

 
https://docs.splunk.com/Documentation/Splunk/latest/SearchReference/Transaction?ref=hk

Hope it helps

algol2
Engager

Hey,

It certainly made a difference, the search now returns thousands of hits.  It looks like it returns the lines I want, but also everything in between, in two-line chunks.

I removed the maxevents=2 argument, which reduces the hit count to 11, but Splunk is still gathering up all these extra entries that don't contain the startswith= or endswith= terms.

0 Karma

yeahnah
Motivator

The transaction command works best when there is a key field (e.g. correlation ID) shared between events that tie the events together.  In this case it can only go on time order, which, depending on what is logging the output, may not be a very reliable way to pair events.

It really comes down to what you are trying to achieve.  Is it just the total time between the first event (startswith) and the very last event (endswith)?  If so, then something like the stats command would be better and far more efficient...

 

search term ... ("Generating reports") OR ("report generation completed")
| eval type=if(searchmatch("Generating reports"), "startswith", "endswith")
| stats min(eval(if(type="startswith", _time, ""))) AS start
        max(eval(if(type="endswith", _time, ""))) AS end
| eval duration=end - start
      ,duration_hm=tostring(duration, "duration")
| foreach start end [ eval <<FIELD>>=strftime('<<FIELD>>', "%c") ]

 


It's important to be clear in what you are aiming to achieve.

Hope this helps
    

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