Chronological Expressions (ChronEx) for Event Logs

• Download source code - 1.6 MB

Introduction

Querying Event logs is downright difficult. Yes it's easy to find an 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.

Let's 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 is at https://github.com/mbadler/ChronologicalExpressions.
• The C# implementation is at https://github.com/mbadler/ChronEx-CSharp.

These are very early and extremely rough implementations. I welcome one and all to submit suggestions, improvements, etc.

C# Implementation

IChronologicalEvent List

All event inputs on ChronEx are lists of IChronologicalEvents:

public interface IChronologicalEvent
    {
        string EventName { get;  }
        DateTime? EventDateTime { 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 instantiate these patterns with preparsed ASTs to speed up builds.

Comparing ChronEx vs. RegEx

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

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

TDEs are simple and much faster that RDEs, however RDEs bring much more power to the table, Non Greedy selectors and look-aheads are items that are not available for TDEs.

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 two 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 it's 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 implemented functionality.

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 currently 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 happened 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 building 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 afternoon the boiler ran for about 8 minutes, that looks excessive.

Running Queries in ChronExQuery

ChronEx has three 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 third 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. Let's find out how many cycles this event covers.

Pattern:

BoilOn

Result:

MatchCount: 389

Ok so now let's 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 it's only listing 350, the reason for that is that other events may occur 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 multiple 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 two 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 let's define a broken cycle as being a BoilOn followed by another BoilOn before another BoilOff.

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 that.

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

• 12^th June, 2018: Initial version