Chronological Expressions (ChronEx) for Event Logs – DEVELOPPARADISE
11/06/2018

Chronological Expressions (ChronEx) for Event Logs

Introduction

Querying Event logs is downright difficult, Yes its easy to find a instance of a specific event , but it can get extremely difficult to find specific patterns of events especially if there are variable elements in the pattern.

Chronological Expressions is a pattern matching specification and reference implementation in C# and soon Python that allows a developer or business intelligence analyst to specify a pattern to match events in a log in a manner similar to RegEx pattern matches on text.

Lets look at this in the context of regex, Suppose you had a log file that could contain events called “A”,”B”,”C”,”D” or “E”. You need to search the log file for all instances of Event A happening twice immediately followed by event B then either Event C or D followed by Event E,

As luck would have it , your log has all of the events saved as a sequence of chars on a single line(a string).

The easiest way to query the log would be to use a regex “A{2}B(C|D)E”. This regex will find all of the instances of this particular pattern in the log.

Expanding this concept into ChronEx , assume those events had more verbose names and were stored in a log. You could use a ChronEx pattern like this:

EventA{2}  EventB  [     EventC     EventD  ]  EventE

This pattern when run against a log file will perform similar to the regex expression when run against a string

 

Using the code

ChronEx is a specification for the pattern matching language. There is also a partial c# reference implementation and I am working on a Python implementation too.

 

The specification is on Github at https://github.com/mbadler/ChronologicalExpressions

The C# implementation is at: https://github.com/mbadler/ChronEx-CSharp

These are very early and extreemly rough implementations. I welcome one and all to suibmit suggestions , improvements etc…

C# Implementation

IChronologicalEvent List

All event inputs on ChronEx are lists of IChronologicalEvents

public interface <code>IChronologicalEvent</code>     {         string <code>EventName</code> { get;  }         DateTime? <code>EventDateTime</code> { get; }     }

 

The library has helper methods that can parse a csv and generate a list of objects suitable for use in the ChronEx

 

The ChronEx Class

The ChronEx class contains methods for running pattern matches

public static bool IsMatch(string ChronExStatment,IEnumerable<IChronologicalEvent> Events)

 This method returns a bool true/false if there were any events pattern that matched

public static int MatchCount(string ChronExStatment, IEnumerable<IChronologicalEvent> Events)

This method returns the number of patterns in the events log (not the number of actual events , but the number of pattern matches)

public static ChronExMatches Matches(string ChronExStatment, IEnumerable<IChronologicalEvent> Events)

This method returns a list of matches including the matched events for each pattern.

These are all static methods that accept the pattern ,Lex,Parse and build the AST (Abstract Syntax Tree) required to run the expression. Eventually we will add methods to instatiate these patterns with preparsed AST’s to speed up builds

Comparing ChronEx vs. RegEx

I stated previously that ChronEx is based on RegEx, Indeed it is , but very loosly so,

Most regex engines nowadays are RDE (Regex Driven Engines) as opposed to what is refered to as TDE (Text Driven Engine). This refers to what drives the engine, do we enumerate on the text or on the pattern,

TDE’s are simple and much faster that RDE’s , however RDE’s bring much more power to the table, Non Greedy selectors and look- aheads are items that are not avaialable for TDE’s

In that vein ChronEx can be considered a EDE (Event Driven Engine?). In that it enumerates over a stream of events and applies the patterns to them. This is for 2 reasons:

  1. It is easier to write as an EDE
  2. Events lend themselves to be processed as streams, In regex – it is expected that you already have the full text you want to process in memory and you can then have the regex move around the text as required. With Event logs we would need the ability to process logs that may contains millions of events , so we need to resort to streams, load the data only when the engine needs it and allow older already processed data to be purged from memory as required. As a matter of fact – while its not implemented yet – I can see having Long Running Real Time patterns that will constantly run and be notified whenever a new event is added to the log and it can in Real Time Pump out matches

 

Currently Implemented Functionality

As of version 0.8 this is the currently implemeted functionaity

Feature Description
   
Selector A verbatim match to the event name
Regex Selector A text starting with a slash and ending with a slash – the regex expression will be used to match with the event name
. (Dot) Matches any event
* When appended to a selector or group – matches 0 or more events that match that selector
? When appended to a selector or group – matches 0 or 1events that match that selector
+ When appended to a selector or group – matches 1+ events that match that selector
! (Negation) When prepended to a selector – will match if the selector does not match
   
Indicates to match but not return/capture a specific event
( ) (AND group) Will match if all items in the group match Nested groups are allowed.(Note: negated and groups (  !(  ) are not currenly allowed)
[ ] (OR group) Will match if any of the selectors in the group match (note , for release 0.8 – only basic selectors are supported in or groups , nested groups will compile but the results will probably be wrong)
{X,X} (Numeric Quantifier) Will match a specific count of events (regex style)

 

 

Trying it out – ChronExQuery

Included in the repository and attached to this article is a simple Pattern Query Application.

It comes with a data set adapted from a building energy monitoring system, the log contains a list of events that happend over a 24 hour period in the building;s bolier

The log looks something like this:

BoilOn,Feb 18 2018  1:21PM BoilOff,Feb 18 2018  1:25PM BoilOn,Feb 18 2018  1:25PM BoilOff,Feb 18 2018  1:26PM BoilOn,Feb 18 2018  1:27PM BoilOff,Feb 18 2018  1:30PM

The buidling owner is reporting that the boiler is costing them a lot in fuel costs and from a quick glance at the first 6 lines of the log we see that indeed over 9 minute period in the after noon the boiler ran for about 8 minutes , that looks excessive.

Running queries in ChronExQuery:

ChronEx has 3 tabs , the first tab has the Log, The second contains the query and the results, If you wanted to analyze other logs – just replace the log in the first tab.

The 3rd tab will show you the serialized AST for the last expression you executed

A quick look at the log tells us that there are many with a BoilOn Events matched with a BoilOff event. We Lets find out how many cycles this event covers

Pattern:

BoilOn

Result:

MatchCount: 389

Ok so now lets see what a typical BoilOn/BoilOff cycle looks like

Pattern:

BoilOn BoilOff

 

Result: (last 4)

Result #347    BoilOn  :  2/19/2018 12:50:00 PM    BoilOff  :  2/19/2018 12:53:00 PM Result #348    BoilOn  :  2/19/2018 12:53:00 PM    BoilOff  :  2/19/2018 12:56:00 PM Result #349    BoilOn  :  2/19/2018 12:56:00 PM    BoilOff  :  2/19/2018 12:58:00 PM Result #350    BoilOn  :  2/19/2018 1:00:00 PM    BoilOff  :  2/19/2018 1:00:00 PM

but wait , before it said that there were 389 results , but now its only listing 350 , the reason for that is that other events may occour while the boiler is running so we need a expression that takes that into account

The following pattern will start with a On , but will then look for a Off, by allowing multipel non Offs

BoilOn !BoilOff* BoilOff

The results show these types of patterns: for example:

Result #280    BoilOn  :  2/19/2018 7:19:00 AM    HTMOn  :  2/19/2018 7:20:00 AM    HMComp  :  2/19/2018 7:20:00 AM    BoilOff  :  2/19/2018 7:22:00 AM

but looking at the last result we see something weird

Result #372    BoilOn  :  2/19/2018 12:59:00 PM    HWOn  :  2/19/2018 1:00:00 PM    BoilOn  :  2/19/2018 1:00:00 PM    BoilOff  :  2/19/2018 1:00:00 PM

There are 2 issues here:

  1. We only got 372 results. we were expecting 389
  2. We have a boilon that is not matched with a BoilOff

So it looks like we have data quality issues too, we need to quantify and see how bad this problem is:

So lets define a broken cycle as being a BoilOn followed by another BoilOn before another BoilOf

This pattern uses a regex to define a negated OR

BoilOn !/BoilOff|BoilOn/* BoilOn !BoilOff* BoilOff

and the results indeed show that we have about 15 broken cycles

for example , these are the last 2 broken cycles:

Result #14    BoilOn  :  2/19/2018 11:57:00 AM    BoilOn  :  2/19/2018 12:00:00 PM    BoilOff  :  2/19/2018 12:01:00 PM Result #15    BoilOn  :  2/19/2018 12:59:00 PM    HWOn  :  2/19/2018 1:00:00 PM    BoilOn  :  2/19/2018 1:00:00 PM    BoilOff  :  2/19/2018 1:00:00 PM

 

So what we will do is define that a boiler run event starts with a BoilOn and ends either at the next BoilOff or if a BoilOn is encountered before tha

This is the pattern we will use:

BoilOn ![   BoilOn   BoilOff ]* BoilOff?

and as expected we have all the results we expected

Result #387    BoilOn  :  2/19/2018 12:59:00 PM    HWOn  :  2/19/2018 1:00:00 PM Result #388    BoilOn  :  2/19/2018 1:00:00 PM    BoilOff  :  2/19/2018 1:00:00 PM

 

 

History

 

New Article