Is there a way to capture a value before a matching pattern that comes after a keyword in a different line of a log file ?

[hbenaicha]

Hi,
i am desperately seeking help as I am a beginner Splunk user and I am struggling to extract the data I need from my logs...Basically I would like to read a timing value that is related to an event received previously (few lines before). Let's take the following example (logging of user interaction with a system UI) :

20141118|14:48:14|TESTUSER   |    19 |                              |                              |  0.01s|  0%
20141118|14:48:16|TESTUSER   |    20 |browse                        |                              |  0.56s| 55%
20141118|14:48:18|TESTUSER   |    21 |browse                        |                              |  0.01s|  0%
20141118|14:48:30|TESTUSER   |    22 |browse                        |                              |  0.02s| 50%
20141118|14:49:00|TESTUSER   |    23 |                              |interesting context           |  0.65s| 47% <== trigger
20141118|14:50:10|TESTUSER   |    24 |ACTION                        |                              |  0.03s|100%
20141118|14:50:15|TESTUSER   |    25 |ACTION                        |                              |  0.01s|  0%
20141118|14:50:19|TESTUSER   |    26 |ACTION                        |                              |  0.00s|  0%
20141118|14:50:19|TESTUSER   |    27 |PROCEED                       |                              |  40s  | 80%  <== HERE ! 
20141118|14:50:24|TESTUSER   |    28 |                              |context1                      |  0.68s| 45%<== ignore this 
20141118|14:50:27|TESTUSER   |    29 |ACTION                        |                              |  0.03s| 66%
20141118|14:50:30|TESTUSER   |    30 |ACTION                        |                              |  0.00s|  0%
20141118|14:50:30|TESTUSER   |    31 |PROCEED                       |                              |  0.05s|100%<== ignore this

The idea is to capture the time spent in PROCEED action once we have received interesting context a few lines before. In this example it would be 40s (7th column, 9th line) and to ignore the 0.05s that comes later, because the triggering acontext is context1 and not "interesting context"...

I tried everything from my (little) knowledge but I was only able to capture the timing that comes in lines containing the PROCEED word and display them in a table where we can see the user and the value using this query

index=myIndex source=MySource sourcetype=mySourceType "PROCEED"| rex "(?<date>\d+)\|(?<time>\d+\:\d+\:\d+)\|(?<user>(\s+|\w+))" | rex "PROCEED\s\|\s\w+\s\+|\s+(?<stime>\d+.\d+)s" | table _time stime date time user

Unfortunately I couldn't find any way to correlate the PROCEED action with "interesting context" that comes before (and ignoring the proceed timing that comes with other contexts).

I hope my question was clear.

Any help/feedback is much appreciated.

Regards,

[wpreston · Accepted solution]

I would suggest trying the transaction command to accomplish this. First, expand your initial search to also include the events with "interesting context", then extract the field you are interested in from the "PROCEED" event, then combine the events using transaction with some parameters so that only the events you are interested in get correlated. Something like this:

index=myIndex source=MySource sourcetype=mySourceType "PROCEED" OR "interesting context" 
| rex "(?<date>\d+)\|(?<time>\d+\:\d+\:\d+)\|(?<user>(\s+|\w+))" 
| rex "PROCEED\s\|\s\w+\s\+|\s+(?<stime>\d+.\d+)s" 
| transaction startswith="interesting context" endswith="PROCEED" maxevents=2

Then add your table or stats command to create your report. Transaction essentially combines the two events you are looking for into a single event. Does this do what you need?

[hbenaicha]

Thank you very much ! This answers my questions and close the case.

[wpreston]

There are a few different ways to handle that, but I think the easiest one is to eval a new field that is the value of "stime" you are interested in and use it in your table. So your search would become:

index=myIndex source=MySource sourcetype=mySourceType "PROCEED" OR "interesting context" 
  | rex "(?<date>\d+)\|(?<time>\d+\:\d+\:\d+)\|(?<user>(\s+|\w+))" 
  | rex "PROCEED\s\|\s\w+\s\+|\s+(?<stime>\d+.\d+)s" 
  | eval relevant_stime=if(fieldname == "PROCEED", stime, null())
  | transaction startswith="interesting context" endswith="PROCEED" maxevents=2
  | table _time time user relevant_stime 

Note that I don't know the name of the field that contains "PROCEED", so I just use "fieldname" in my eval statement. Be sure to update it with the proper field name for this statement to work.

[hbenaicha]

Hi Wpreston,
That worked great, brilliant. Thank you very much !

I still have a small issue though, when I generate the report using table I capture 2 timings, the 40s that I wanted, but also the 0.65s that comes near "Interesting context" in the example above

 index=myIndex source=MySource sourcetype=mySourceType "PROCEED" OR "interesting context" 
 | rex "(?<date>\d+)\|(?<time>\d+\:\d+\:\d+)\|(?<user>(\s+|\w+))" 
 | rex "PROCEED\s\|\s\w+\s\+|\s+(?<stime>\d+.\d+)s" 
 | transaction startswith="interesting context" endswith="PROCEED" maxevents=2
 | table _time time user stime 

(unfortunately I don't have enough karma points to add a screenshot)