How can I write a search to calculate the sequence of delays for incoming and outgoing log messages?

[jgcsco]

I need to find out if my application received the messages late or processed it late. Here are the messages from the log:

yyyy/mm/dd hh:mm:ss incoming  event_starttime=yyyy/mm/dd hh:mm:ss

<... other messages in the log...>

yyyy/mm/dd hh:mm:ss outgoing  event_starttime=yyyy/mm/dd/ hh:mm:ss

where:
tid- "transaction id" and starttime will be the same for incoming/outgoing log messages.

The tasks is to find out:

If event_starttime < log timestamp of incoming message

|stats count incoming_late

If event_starttime > log timestamp of incoming message, and event_starttime < log timestamp of outgoing message

|stats count outgoing_late

How should I do this in Splunk?

Thanks

[cpetterborg]

One has to assume that the tid is also in the start and end events, though you don't have them in your example data, and that incoming and outgoing come directly before the event_starttime.

<your search> | rex field=_raw "incoming\s*event_starttime=(?P<istarttime>\S+\s+\S+)" | rex field=_raw "outgoing\s*event_starttime=(?P<ostarttime>\S+\s+\S+)" | eval starttime=strftime(_time, "%Y-%M-%D %h:%m:%s") | eval indelay=strftime(istarttime,"%Y/%M/%D %h:%m:%s")-starttime | eval outdelay=strftime(ostarttime,"%Y/%M/%D %h:%m:%s")-starttime | eval transaction tid | search indelay<0 OR outdelay<0

This should list the set of events (tied by the tid) that are late.

[jgcsco]

Thanks for you response! Sorry for the delay as I was out of the office. You are right, there is "tid" in the start/end event. I missed it in my example data. I have a question regarding "_time". How could I determine if this time is associate with incoming event log timestamp or outgoing event log timestamp?

[cpetterborg]

There is an _time associated with each event. In my solution above, the conversion of the _time value is done so that it is a unix timestamp in order to do subtraction. In that search it will calculate either the indelay for an event or an outdelay. when you tie the events together with the transaction command it provides the (then) single event with both of them. if either of the delays are negative, then you have your events that are out of bounds.

Did I answer your question? 🙂 I hope so, but ask again if not.