We're experimenting with Drools to process a large amount of textual data from log files. I'm trying to understand how to properly measure an event time.
The event in question begins in one log line, but may finish either by a successful completion or an unusual abort. That's what I'm having problems capturing. Here's how the log entries might look (when the other log lines are filtered out):
Jan 24 06:50:29 app[623]: CallOriginateCmd
Jan 24 07:19:27 app[616]: Client ended the call
Jan 24 09:00:18 app[623]: CallOriginateCmd
Jan 24 09:34:48 app[616]: Client ended the call
Jan 24 11:03:56 app[623]: CallOriginateCmd
Jan 24 12:56:58 app[616]: Client ended the call
Jan 24 15:48:11 app[623]: CallOriginateCmd
Jan 24 16:13:24 app[616]: Client ended the call
Jan 24 17:16:16 app[623]: CallOriginateCmd
Jan 24 18:48:51 app[616]: Client ended the call
Jan 25 06:09:01 app[623]: CallOriginateCmd
Jan 25 06:09:24 app[623]: Failure: timeout sending Config
Jan 25 06:09:26 app[623]: CallOriginateCmd
Jan 25 06:09:50 app[623]: Failure: timeout sending Config
I'm trying to create rules which links the Jan 24 06:50:29 call with the 07:19:27 termination, the Jan 25 06:09:01 call with the 06:09:24 failure, etc. My rules below do not create a Call() object with the right start/end times that I would like.
Here's the outline of my code:
rule "Found Call Start"
when
LogEntry( message matches ".*CallOriginateCmd.*", logTimestamp : timestamp )
then
Call call = new Call();
call.setStarttime( logTimestamp );
call.setPartial ( true );
insert( call );
AnalysisLog.debug( logTimestamp, "Call Started" );
end
rule "Found Call End"
when
LogEntry( message matches ".*Client ended the call.*", logTimestamp : timestamp )
call : Call( partial == true )
then
call.setEndtime( logTimestamp );
call.setPartial( false );
call.setFailure( false );
update( call );
AnalysisLog.debug( logTimestamp, "Call Ended." );
end
rule "Found Call Failure"
when
LogEntry( message matches ".*timeout sending Config.*", logTimestamp : timestamp )
call : Call( partial == true )
then
call.setEndtime( logTimestamp );
call.setPartial( false );
call.setFailure( true );
update( call );
AnalysisLog.debug( logTimestamp, "Call Failed." );
end
The output from above is:
Jan 17 22:53:04: Call Started
Jan 18 02:10:23: Call Failed.
Jan 17 23:09:23: Call Started
Jan 18 02:10:23: Call Failed.
Jan 17 23:25:39: Call Started
Every call seems to match Failed, although only the last call in the log should have matched.
I thought that the code:
call : Call( partial == true )
within the "when" clause would link the start+end or start+abort together, but this apparently doesn't do this.
Instead, I suppose I need to find a way in the "when" clause to find the call where the logTimestamp is closest to the Starttime of the call. Is this possible?
TIA
I am not seeing any correlation fields in your log, so I a assuming that the messages are always sequential? i.e., a message starts a call and the next message either completes or fails the call. If that is the case, there are many ways of doing it, but you can try something like this:
rule "Found Call End"
when
$s : LogEntry( message matches ".*CallOriginateCmd.*" )
$e : LogEntry( message matches ".*Client ended the call.*" )
not LogEntry( timestamp > $s.timestamp && timestamp < $e.timestamp )
then
Call call = new Call();
call.setStarttime( $s.getTimestamp() );
call.setEndtime( $e.getTimestamp() );
call.setFailure( false );
retract( $s );
retract( $e );
insert( call );
AnalysisLog.debug( logTimestamp, "Call Ended." );
end
Write a similar rule for your call failed scenario. If there are correlation fields in your log, just add constraints to correlate the correct LogEntries.