Why when using transaction to calculate duration after a dedup doesnt return values wanted?

[stuwoodward]

Hi All,

I am new to splunk and not a developer so first up apologies for any poor syntax or coding practices.

What am I trying to do?

• The information that i need to show when a batch starts and ends is in different formats in different logs
• I am trying to come up with a table that shows how long it takes to run each batch of transactions.

What is in the logs?

• There is a batch id in each of the logs but in a different format so i use regex to extract it. This is what I want to group on
• There is a unique string in 1 log per batch which contains "Found the last" which is my end time 
• For each transaction in the batch there is a log which contains ""After payload". If there are 100 entries in the batch there are 100 logs with this message. I want to use the first of these logs as my start time.

How am I trying to do it?

I am filtering out any unneccesary logs by only looking for logs that have the message that I want which works

source="batch-queue-receiver.log"
| rex field=_raw "[\? ]Batch\s?[iI][dD]\s?: (?<Batchid>.{7}+)"
| rex field=_raw "[\? ]MerchantId: (?<Merchantid>.{7}+)"
| rex field=_raw "[\? ]INFO a.c.s.b.q..+- (?<info>.{14}+)"
| where Batchid != ""
| where info = "Found the last" OR info = "After payload "

 I then want to use transaction to group by batch. This works but because I have multiple entries per batch it takes the last entry not the first so my duration is much smaller than expected

source="batch-queue-receiver.log"
| rex field=_raw "[\? ]Batch\s?[iI][dD]\s?: (?<Batchid>.{7}+)"
| rex field=_raw "[\? ]MerchantId: (?<Merchantid>.{7}+)"
| rex field=_raw "[\? ]INFO a.c.s.b.q..+- (?<info>.{14}+)"
| where Batchid != ""
| where info = "Found the last" OR info = "After payload "
| transaction Batchid startswith="After payload conversion" endswith="Found the last message of the batch" mvlist=true| table Batchid duration

I then try to dedup but get no values returned

source="batch-queue-receiver.log"
| rex field=_raw "[\? ]Batch\s?[iI][dD]\s?: (?<Batchid>.{7}+)"
| rex field=_raw "[\? ]MerchantId: (?<Merchantid>.{7}+)"
| rex field=_raw "[\? ]INFO a.c.s.b.q..+- (?<info>.{14}+)"
| where Batchid != ""
| where info = "Found the last" OR info = "After payload "
| dedup info Batchid sortby +_time
| table Merchantid Batchid _time info _raw
| transaction Batchid startswith="After payload conversion" endswith="Found the last message of the batch" mvlist=true| table Batchid duration

If I remove the transaction but keep the dedup I get only two messages per batchid (what I want) so I am not sure what is going wrong . It appears that I can't do a transaction after a dedup but it is probably something else I am not aware of. Any help would be appreciated.

source="batch-queue-receiver.log"
| rex field=_raw "[\? ]Batch\s?[iI][dD]\s?: (?<Batchid>.{7}+)"
| rex field=_raw "[\? ]MerchantId: (?<Merchantid>.{7}+)"
| rex field=_raw "[\? ]INFO a.c.s.b.q..+- (?<info>.{14}+)"
| where Batchid != ""
| where info = "Found the last" OR info = "After payload "
| dedup info Batchid sortby +_time
| table Batchid _time info

[ITWhisperer · Accepted solution]

Rather than using transaction, you could use stats

| rex field=_raw "[\? ]Batch\s?[iI][dD]\s?: (?<Batchid>.{7}+)"
| rex field=_raw "[\? ]MerchantId: (?<Merchantid>.{7}+)"
| rex field=_raw "[\? ]INFO a.c.s.b.q..+- (?<first>After payload )"
| rex field=_raw "[\? ]INFO a.c.s.b.q..+- (?<last>Found the last)"
| where isnotnull(first) OR isnotnull(last)
| eval firsttime=if(isnotnull(first),_time,null())
| eval lasttime=if(isnotnull(last),_time,null())
| stats earliest(firsttime) as firsttime latest(lasttime) as lasttime by Batchid
| eval duration = lasttime-firsttime

[stuwoodward]

Thanks @ITWhisperer your solution did the job