Search for time interval in logs

Intro

This post is indirectly related to my mini-series about log analysis. It would be great to read the two main parts to better understand what I'm talking about. Part 1, Part 2.

This post describes one important problem I ran into while implementing the IDE approach. 

Task Description

When someone is working with logs usually he or she needs to investigate only one time interval. The available logs usually span days but the time interval that must be investigated is 1-2 hours. The task is to select all log records within that time interval. 

Basic Log Record Regex

In order to select a log record we need a regular expression that matches any log record. For the simple log4j format like 

2018-08-10 11:00:56,234 DEBUG [Thread-1] package1.pkg2.Class1 Text Message

I found the following regex:
TIME_REGEX((?!(TIME_REGEX)).*\r?\n)*

This regular expression matches both single-line and miltiline log records. Time regex could be 

\d\d\d\d-\d\d-\d\d \d\d:\d\d:\d\d,\d\d\d

So if somebody wanted to load all logs into a text window he could open the log files one by one and use Matcher.find() with this regex to get all log records. 

This regex is based on the fact that the time regex pattern is never repeated in the body of the log message which is true in 99% of all cases. 

Datetime of the Log Record

In order to search for a specific time interval and use other features it makes sense to extract the dtaetime information from the log record. Thankfully this task has been solved by JDK with DateTimeFormatter. It is enough to specify the format for the log type and the date can be extracted. For example for the log record above the format is

yyyy-MM-dd HH:mm:ss,SSS

As soon as we can extract the datetime information we can specify the interval as datetime values not Strings in some specific format.

Search Time

Now that we have found a way to select any log record and extract the date information from it the path forward seems clear: 

• specify the interval, 
• select the records one by one
• extract the date information from the log record
• compare the datetime with the interval
• if the datetime is within the interval add this record to the List of found records
• after searching through all files show the found records 

There is one big issue with this approach: time. With 50 log files 50 MB each it will take hours to scan all them to find 10 MB of records in the interval. 

Solution

We can use one trick to filter out the files that do not contain a single record in the interval. We use the fact that the log records in the log files are written one after the other. This means the time of the next record is equal or after the time of this record. For example only 2 situations are possible:

2018-08-10 11:00:56,234 DEBUG [Thread-1] package1.pkg2.Class1 Text Message

2018-08-10 11:00:56,234 DEBUG [Thread-1] package1.pkg2.Class1 Msg 2

Or

2018-08-10 11:00:56,234 DEBUG [Thread-1] package1.pkg2.Class1 Text Message

2018-08-10 11:00:56,278 DEBUG [Thread-1] package1.pkg2.Class1 Msg 2

I rarely saw some examples where under high load the log records can go in reverse but the difference is in milliseconds. We can consider this difference insignificant for our purpose. 

This means if neither the first nor the last record in the file are not in the interval all the records in the file are not in the interval and this file can be filtered out. Java regular expressions have special constructs to find the first and the last records.

The first record:

\ATIME_REGEX((?!(TIME_REGEX)).*\r?\n)*

The last record:
TIME_REGEX((?!(TIME_REGEX)).*\r?\n)*\Z

\A means the beginning of the text, \Z means the end of the text. You can find more details in the javadocs for java.util.regex.Pattern. 

The solution is to use a special prescanning technique. Before scanning the whole text of a log file find the first and last records and if non of them is in the interval skip the file. Of the 50 files maybe 1-2 needs to be scanned. 

Conclusion

REAL uses this technique to speed up searches for a datetime interval. I found that it takes approximately 5-10 seconds to decide if the file must be skipped. Most of the time if spent executing Matcher.find() for the last record. The first record is found much faster. I think it is possible to speed it up even further by selecting the last 5 MB of a 50 MB file to search for the last record. But even in the current state it is fast enough. 

IDE approach to log analysis pt. 2

Intro

In the first part I explained the theoretical approach to log analysis that I think is best for a sustain engineer. This engineer doesn't need to analyze logs immediately as they come but instead is focused on a deep analysis of complicated issues. In this second part I'll show that many search scenarios can be covered with one sophisticated template and show a working prototype.

Search Object Template

The main requirement for the search template is it must be sophisticated, very sophisticated in the best case. The less manual search the better. A sophisticated template should do most of the work and do it fast. As we don't have any servers here only the developer's PC which is expected to handle 2-3 GB of logs speed is also important. 

Main Regular Expressions

The template should declare some regular expressions which will be searched for (with Matcher.find) in the logs. If more than one is declared first the results for the first are collected, then for the second etc. In the most general sense the result of a search is an array of String - List<String>. 

Acceptance Criteria

Not all results are accepted by the searching process. For example the engineer can search for all connection types excluding "X". Then he or she can create an acceptance criterion and filter them out. by specifying a regex "any type but X". Another possibility is searching within a time interval. The engineer can search for any log record between 10 and 12 hours (he or she has to enter the complete dates of course). 

Looking for distinct expressions is also possible. In this case the engineer specifies one more regular expression (more than one in the general case). An example will explain this concept better. 

distinct regex: connection type (q|w)

log records found by the main regex:

connection type w found

connection type q created

connection type s destroyed

connection type q found

The result of a distinct search:

connection type w found

connection type q created

Parameters

One of the issues with regular expressions is that really useful regular expressions are very long and unwieldy. Here is a sample date from a log:

2018-08-06 10:32:12.234

And here is the regex for it:

\d\d\d\d-\d\d-\d\d \d\d:\d\d:\d\d.\d\d\d

The solution is quite simple - use substitution. I call them parameters for the regex. Some parameters may be static like the time for the record but some may be defined by the user. Immediately before the execution the parameters are replaced with the actual values.

Views

The result of the search is a log record i.e. something like

2018-08-06 10:32:12.234 [Thread-1] DEBUG - Connection 1234 moved from state Q to state W \r?\n

While it is great to find what was defined in the template it would be even better to divide the information into useful pieces. For example this table represents all the useful information from this record in a clear and concise way:

Connection	1234	Q	->	W

To extract this information pieces we can use the "view" approach. This means declaring smaller regexes that are searched for in the log record and return a piece of information about the log record. It is like a view of this log record. Showing it all in a table makes it easier to read. Also a table can be sorted by any column.

Sort and Merge

The most efficient way to make this kind of search with the template is use a thread pool and assign every thread to a log file. Assuming there are 3-4 threads in the pool the search will work 3-4 times faster. But merging results becomes an important issue. There can be 2 solutions here:

1. Merging results. We need to make sure that the results go in the correct order. If we have 3 log files, the first one covering 10-12 hours, the second 12-14, the third 14-17 then the search results from those file must go in the same order. This is called merging.
2. Sorting results. Instead of merging them we can just sort them by date and time. Less sophisticated but simple.

Merging looks like a more advanced technique which allows us to keep the original order of records.

Workflow

Final Thoughts

The question that must be nagging everyone who has reached this point in this post is: Has anyone tried to implement all this? The answer is yes! There is a working application that is based on the Eclipse framework, includes a Spring XML config and a lot of other stuff. The search object templates work as described in this article.

Here is the Github link:

https://github.com/xaltotungreat/regex-analyzer-0
Why 0? Well it was meant to be a prototype and to some extent is still is. I called this application REAL
Regular
Expressions
Analyzer
for Logs

It is assumed the user has some knowledge how to export an Eclipse RCP application or launch it from within the Eclipse IDE. Unfortunately I didn't have enough time to write any good documentation about it. By default it can analyze HBase logs and there are a lot of examples in the config folder. 

IDE approach to log analysis pt. 1

Intro

I think most software engineers understand the importance of logs. They have become part of software development. If something doesn't work we try to find the cause in the logs. This could be enough for simple cases when a bug prevents an application from opening a window. You find the issue in the logs, look it up on Google and apply the solution. But if you are fixing bugs in a large product with many components analyzing logs becomes the main problem. Usually sustain engineers (who are fixing bugs not developing new features) need to work with many hundreds of megabytes of logs. The logs are usually split into separate files 50-100 MB each and zipped. 

There are several approaches to make this work easier. I'll describe some existing solutions and then explain a theoretical approach to this problem. This blog post will not discuss any concrete implementations. 

Existing Solutions

Text Editor

This solution is not actually a solution it is what most people would do when they need to read a text file. Some text editors could have useful features like color selection, bookmarks which can make the work easier. But still the text editor falls short of a decent solution.

Logsaw

This tool can use the log4j pattern to extract the fields from your logs. Sounds good but these fields are already obvious from the text. Clearly the improvement is insignificant over a simple text editor. 

LogStash

This project looks pretty alive. But this approach is quite specific. Even though I've never worked with this tool from the description I understood that they use ElasticSearch and simple text search to analyze logs. The logs must be uploaded somewhere and indexed. After that the tool may show the most common words, the user may use text search etc. Sounds good, seems to be some improvement. Unfortunately not so much. Here are the cons:

• Some time is required to begin working with the logs. One has to upload them, index them. After the work is done these logs must be removed from the system. Looks like a little overkill if the logs are meant to be analyzed and discarded. 
• A lot of components involved with a lot of configuration necessary.
• Full text search is not very useful with logs. Usually the engineer is looking for something like "connection 2345 created with parameter 678678678". Looking for "created with parameter" will return all connections. Looking for "connection 2345" will return all such statements but usually there is only one - when this connection was created.

Other Cloud-based Solutions

There are a lot of cloud-based solutions available. Most of them have commercial plans and some have free plans. They offer notifications, visualizations and other features but the main principles are the same as for LogStash. 

Log Analysis Explained 

To understand why these solutions do not perform well for analyzing complex issues we need to try to understand the workflow. Here is a sample workflow with the text editor:

1. An engineer received 1 GB of logs with the information that the bug happened at 23:00 with request ID 12345.
2. First he or she tries to find any errors or exceptions around that time.
3. If that fails the engineer has to reconstruct the flow of events for this request. He or she begins looking for statements like "connection created", "connection deleted", "request moved to this stage" trying to narrow down the time frame for the issue. 
4. That is usually successful (even though could take a lot of time) now it is clear that the issue happened after connection 111 was moved to state Q. 
5. After digging a little more the engineer finds out that this coincides with connection 222 moving to state W. 
6. Finally the engineer is delighted to see that the thread that moved connection 222 to the new state also modified another variable that affected connection 111. Finally the root cause.

In this workflow we see that the engineer most of the time is looking for standard strings with some parameters. If only it could be simplified...

IDE approach

There are several parts to the IDE approach.

1. Regular expressions. With regular expressions one can specify the template and search for it in the logs. Looking for standard strings is much simpler with regular expressions. 
2. Regular Expressions Configuration. The idea here is that standard strings like "connection created \d{5}\w{2}", "connection \d{5}\w{2} moved to stage \w{7}", "connection\d{5}\w{2} deleted" do not change often. Writing the regular expression to find it every time is unwieldy because such regexes could be really long and complicated. It is easier if they can be configured and used by clicking on a button.
3. IDE. We need some kind of an IDE to unite this together. To read the configuration, show the logs files and stored regexes, display the text and search results. Preferably like this:
   
4. Color features. From experience I know that log analysis is much easier when you can mark some strings with color to easily see it in the logs. Most commercial log analyzer tools use color selection. The IDE should help with that.

Pros and Cons

Pros of the IDE approach:

1. No cloud service necessary. No loading gigabytes of logs somewhere, no cloud configuration. One only has to open the IDE for logs, open the log folder and start analyzing.
2. If the IDE is free the whole process is completely free. Anyway should be cheaper than a log service.

Cons of the IDE approach:

1. Most cloud services offer real-time notifications and log analysis "on the fly". It means as soon as the specified exception happens the user is notified. The IDE approach cannot do that.
2. The requirements for the user's PC are somewhat higher because working with big strings in Java consumes a lot of memory. 8 GB is the minimum requirement from my experience. 

The bottom line is the IDE approach is suitable to analyze complicated issues in the logs. It cannot offer real-time features of cloud services but should be much cheaper and easier for analyzing and fixing bugs. 

Final Thoughts

It would be great if someone could implement this great approach! I mean create this IDE with all those features and make log analysis easier for everyone! I know from experience that this could be a tedious work that feels harder than it actually is. In the next post (part 2) I'll explain the difficulties/challenges with this approach and offer a working implementation based on the Eclipse framework.