Time Calculation between two events in XML format

[anilkashyap]

Hi

I have below logs where these two events appear multiple time along with other events

<Message>
    <ID>00000000-0000-0000-0000-000000000000</ID>
    <Date>2019-04-27 19:33:27.06</Date>
    <Text>Launched application: MMViewer, PID: 7988</Text>
    <Category></Category>
    <Source>Workflow</Source>
    <Level>Event</Level>
    <Class>General</Class>
    <Module>WorkflowHost</Module>
    <Method></Method>
    <FileName></FileName>
    <LineNumber>0</LineNumber>
    <ProcessID>6836</ProcessID>
    <User>e1e2f1a39246e0cc7e611c8d180e8f6c</User>
    <Parameters></Parameters>
</Message>

<Message>
    <ID>00000000-0000-0000-0000-000000000000</ID>
    <Date>2019-04-27 19:34:42.04</Date>
    <Text>Application: MMViewer, PID: 7988 failed</Text>
    <Category></Category>
    <Source>Workflow</Source>
    <Level>Warning</Level>
    <Class>General</Class>
    <Module>WorkflowHost</Module>
    <Method></Method>
    <FileName></FileName>
    <LineNumber>0</LineNumber>
    <ProcessID>6836</ProcessID>
    <User>e1e2f1a39246e0cc7e611c8d180e8f6c</User>
    <Parameters></Parameters>
</Message>

I want to select these two events and form a table which calculate the after how much time "Application: MMViewer, PID: 7988 failed" event happened after "Launched application: MMViewer, PID: 7988" something like

Table like
EventLaunch Date&Time EventFailed Date&Time Duration (Time2-Time1)

I am not able to select two lines, it always return line which satisfy the condition after "OR" when i am using
"Launched application:" OR Application: PID failed

[dmarling]

Here's a run anywhere example using the data you provided that accomplishes you goal. This is making a couple assumptions that I would need you to confirm:

| makeresults count=1
| fields - _time
| eval data="<Message>
     <ID>00000000-0000-0000-0000-000000000000</ID>
     <Date>2019-04-27 19:33:27.06</Date>
     <Text>Launched application: MMViewer, PID: 7988</Text>
     <Category></Category>
     <Source>Workflow</Source>
     <Level>Event</Level>
     <Class>General</Class>
     <Module>WorkflowHost</Module>
     <Method></Method>
     <FileName></FileName>
     <LineNumber>0</LineNumber>
     <ProcessID>6836</ProcessID>
     <User>e1e2f1a39246e0cc7e611c8d180e8f6c</User>
     <Parameters></Parameters>
</Message>

<Message>
     <ID>00000000-0000-0000-0000-000000000000</ID>
     <Date>2019-04-27 19:34:42.04</Date>
     <Text>Application: MMViewer, PID: 7988 failed</Text>
     <Category></Category>
     <Source>Workflow</Source>
     <Level>Warning</Level>
     <Class>General</Class>
     <Module>WorkflowHost</Module>
     <Method></Method>
     <FileName></FileName>
     <LineNumber>0</LineNumber>
     <ProcessID>6836</ProcessID>
     <User>e1e2f1a39246e0cc7e611c8d180e8f6c</User>
     <Parameters></Parameters>
</Message>"
| rex mode=sed field=data "s/\n\n/~/g"
| makemv data delim="~" 
| mvexpand data
| spath input=data 
| eval "Message.Date"=strptime('Message.Date', "%Y-%m-%d %H:%M:%S.%2N")
| eval Launched=if(match('Message.Text', "Launched"), 'Message.Date', null())
| eval LaunchName=if(match('Message.Text', "Launched"), 'Message.Text', null())
| eval Failed=if(match('Message.Text', "failed"), 'Message.Date', null())
| stats values(LaunchName) as "Launched Application" values(Launched) as Launched values(Failed) as Failed by "Message.ID"
| fieldformat Launched=strftime(Launched, "%Y-%m-%d %H:%M:%S.%2N")
| fieldformat Failed=strftime(Failed, "%Y-%m-%d %H:%M:%S.%2N")
| eval duration=Failed-Launched

1. The ID in the message always matches between the failed/launched events
2. The fields are automatically extracted by Splunk. I used the spath command to manually have it extracted, but that is not recommended to run on all your events as it can consume a lot of memory on your search head at execution time. If that's not the case I can show you how to run spath in an eval so it only pulls that specific field.

[dmarling]

It appears to have stripped the xml markup I copy/pasted from your original example. I'll work to get that fixed.

[dmarling]

I have appeared to identify a defect with the markup code. If you post a code snippet after a ordered list, it breaks the code snippet functionality.

[dmarling]

Here's an updated run anywhere example that will use spath in the evals to try to limit the amount of memory you need when running the query. It will be difficult to deal with the multiple events in a single event until you get your conf line breaks fixed on these events. This query is assuming the ID on the message is what is used to unite the two messages. If that is not the case let me know:

| makeresults count=1 
| fields - _time 
| eval data="<Message>
<ID>00000000-0000-0000-0000-000000000000</ID>
<Date>2019-04-27 19:33:27.06</Date>
<Text>Launched application: MMViewer, PID: 7988</Text>
<Category></Category>
<Source>Workflow</Source>
<Level>Event</Level>
<Class>General</Class>
<Module>WorkflowHost</Module>
<Method></Method>
<FileName></FileName>
<LineNumber>0</LineNumber>
<ProcessID>6836</ProcessID>
<User>e1e2f1a39246e0cc7e611c8d180e8f6c</User>
<Parameters></Parameters>
</Message>

<Message>
<ID>00000000-0000-0000-0000-000000000000</ID>
<Date>2019-04-27 19:34:42.04</Date>
<Text>Application: MMViewer, PID: 7988 failed</Text>
<Category></Category>
<Source>Workflow</Source>
<Level>Warning</Level>
<Class>General</Class>
<Module>WorkflowHost</Module>
<Method></Method>
<FileName></FileName>
<LineNumber>0</LineNumber>
<ProcessID>6836</ProcessID>
<User>e1e2f1a39246e0cc7e611c8d180e8f6c</User>
<Parameters></Parameters>
 </Message>" 
| rex mode=sed field=data "s/ +</</g" 
| rex mode=sed field=data "s/\n +\n/\n\n/g" 
| rex mode=sed field=data "s/\n\n/█/g" 
| makemv data delim="█" 
| mvexpand data 
| eval "Message.Date"=strptime(spath(data, "Message.Date"), "%Y-%m-%d %H:%M:%S.%2N") 
| eval Launched=if(match(spath(data, "Message.Text"), "Launched"), 'Message.Date', null()) 
| eval LaunchName=if(match(spath(data,"Message.Text"), "Launched"), spath(data,"Message.Text"), null()) 
| eval Failed=if(match(spath(data,"Message.Text"), "failed"), 'Message.Date', null()) 
| eval "Message.ID"=spath(data, "Message.ID")
| stats values(LaunchName) as "Launched Application" values(Launched) as Launched values(Failed) as Failed by "Message.ID" 
| fieldformat Launched=strftime(Launched, "%Y-%m-%d %H:%M:%S.%2N") 
| fieldformat Failed=strftime(Failed, "%Y-%m-%d %H:%M:%S.%2N") 
| eval duration=Failed-Launched

[dmarling]

Is each message xml a seperate event in Splunk or are they in the same event? The answer to this will determine how best to answer your question.

[anilkashyap]

Thanks for putting effort to solve this.
one log file contains such multiple events, every event is of same format, file extension is not xml but a .log hence splunk might see this as plan text logs file.

[dmarling]

gotcha, a longer term solution would be to have your conf files adjusted so that your line breaks are on each <message> xml flag and that your event time is taken from the date portion of the message. That will make it easier to perform your requested statistical analysis to derive the duration. That being said, the answer I provided in the answer section can still work, but it will need to be tweaked to be more efficient as using sdata on every event plus a mvexpand will blow up the memory utilized in your query quite a bit. I'll comment on my solution below a more efficient query to extract the required fields via a spath eval.