Skip to end of metadata
Go to start of metadata

The tool described here is currently an experimental prototype.

In order to facilitate viewing large log files we have created a tool called midPoint Log Viewer. It is an Eclipse plugin that displays log files in a well-arranged way, mainly by utilizing Eclipse Outline and Problems views.

Features

Showing log outline

Log Viewer can provide a tree view of a (large) log file, giving quick overview of its content and allowing to drill down to details we are interested in. The viewer provides a default configuration showing some standard levels. However, it also allows to change their arrangement, as well as to add new outlining rules based on substring and regular expressions matching.

Standard levels are:

LevelContentDescription
10System startup headerMarks the "system startup" event, recognized by the header that is printed out on startup.
20Individual test method levelUseful for viewing test logs. Expects individual tests to be marked by "TestUtil): =====[ ..... ]=====" text. For production logs, this outline level is simply not used.
25Test method partsDelineates When and Then parts of the test method execution.
30Execution summaryShows summaries of individual operations, marked by "###[ CLOCKWORK SUMMARY ]###" text.
40Model context dumpShows model context dumps provided as part of executing particular operations. These are marked by texts such as "---[ PROJECTOR ... ]---" or "---[ CLOCKWORK ... ]---".
50Projection context dumpProjection contexts that are part of the model context dumps.
50Delta executionRecord of a delta execution, either in repository or on a resource. Marked by "---[ Going to EXECUTE delta ... ]---" text.
50Mapping evaluationSummary of evaluation of a mapping, marked by "---[ MAPPING ... ]---" text. Note this is on the same level as a projection context, just below model context dump.
70Expression evaluationSummary of evaluation of an expression (in the context of a mapping or standalone). Marked by "---[ EXPRESSION ... ]---" text.
80Script executionSummary of execution of a script - usually in the context of expression evaluation. Marked by "---[ SCRIPT ...]---" text.

An example - showing the result of the workflow module tests:

We can see there are four system runs. For example, the first one starts at 14:10:35 and is covered by lines 117-196689. After clicking on a line in the outline the cursor in main window jumps to appropriate log line.

Now we can explore the system run by expanding e.g. the first system startup node. We see there is a couple of test methods executed.

So we select e.g. the test080 and expand its node. There is one operation execution; after expanding it we see the following:

There is a lot of context dumps, as the operation traverses through specific execution stages. Columns have the following means:

Column / fieldDescription
Wave m : nExecution (m) and projection (n) wave number (0, 1, ...)
P: nNumber of projections in this context dump
M: nNumber of mappings evaluated since last context dump
#Indicates there are some executions since last context dump
DeltaTime since last context dump - useful to diagnose performance problems
From startTime since first context dump in this operation
ThreadThread in context of which this log line was recorded.

Threads can be especially problematic when analyzing log files. The outline is currently not adapted to reasonably display output from more than one thread at once (i.e. the tree structure and related information will most probably look like nonsense). That's why we show Thread column in the outline. The user can then simply select which threads he wants to display in the outline by using %show-in-outline instruction (in the future, also GUI option will be provided).

In this particular case mixing threads is not a problem, because during workflow tests first part of processing (INITIAL stage) occurs in the context of calling thread, but other parts (starting with PRIMARY stage) occur in the background; the serialized nature of processing is preserved.

Other levels are similar to this:

Configuring the outline

This is the standard configuration:

You can remove some of these levels or reorganize them. For example, if you prefer more flat structure, you could put some of the definitions to the same level. E.g. startup and test. Or operation-summary with operation-context. Some combination do not make sense, and some could make sense but the viewer was not tested with them. So it is not guaranteed that the output would be meaningful in all cases.

You can also add custom levels. For example, the following are definitions equivalent to %outline startup and %outline test ones:

"Containing" is a keyword that selects a line containing a given text. "Matching" does the same, but interprets the text as a regular expression. 10 and 20 are the levels. Strings at line ends denote the labels that would be shown in the outline. (${date} means date and time from the log line; ${group:1} means first group after successfully matching given regex.)

As said above, you can specify which lines to include into or exclude from the outline. An example:

This instructs viewer to make outline only from lines that have either "[Thread-21]" or "[Thread-22]" in their corresponding "log line header" (i.e. first line of the - potentially multiline - log entry). All other items will not be shown in the outline, as prescribed in the third instruction.

Syntax description

Cause lines of give <type> outlined at give <level>. Type = (startup, test, test-part, operation-summary, operation-context, projection-context, execution-mapping, expression, script). Note: recommended to use approximately in this order; projection-context, execution and mapping should be one level below operation-context.

Lines fulfilling condition are displayed in outline at given <level> with given <text> in outline.

Lines fulfilling condition (or all lines if condition is not specified) are included in the outline, or excluded from it.

Condition can consist of a set of atomic condition clauses connected by "and":

Item specifies what is to be taken into account when evaluating the condition. It is either current line, whole log entry, or header (first line) of the log entry. If not specified, a reasonable default is used (most often "line", but e.g. in %kill-entry the whole entry is considered by default).

Text is either plain text (for containing/not-containing operator) or a regular expression (for matching/not-matching operator). Do not forget to include .* at beginning and end if you want to match for something inside a line/entry.

Showing error, warning and information messages

Sometimes it is useful to see whether something went wrong during midPoint execution. Traditionally we search through the logfile for strings like "ERROR", "Exception" etc., browsing through false alarms to find the cause of a problem we fight with.

Log viewer can display errors, and even warnings and selected information messages in Eclipse "Problems" view as errors, warnings and infos. Like this:

In order to eliminate false alarms, this feature is configurable, with the default of:

Rules 1-3 inhibit often-occurring errors. Rule 4 tells the viewer to display log errors as Eclipse errors. Warnings and information messages are not shown by default.

Another example could be:

The result would be that all lines with the given exception are show as warnings. Second rule states that lines with given OID which are not a part of profiling logging entries (those that have "PROFILING" in the first line of the log entry) are shown as infos.

Another example: diagnosing failed TestSecurity.test204 test: wanting to quickly browse through security-related subtests. So added this

and got this:

A special case is marking all lines that took longed than N milliseconds to appear either as errors, warnings or infos. This is quite rudimentary way of diagnosing potential or real performance problems.

An example:

Syntax description

If delay between successive log lines is at least <n> milliseconds, marks the line as <level> (error, warn, info).

Marks ERROR/WARN/INFO lines (optionally fulfilling a condition) as <severity> (error, warn, info, none).

Marks arbitrary lines fulfilling a condition as <severity>.  

Folding (collapse + expand)

Structures in log files - like context dumps - can be quite extensive and complex. It is useful to be able to collapse and later expand back parts of these structures.

There are three kinds of folding available:

  1. Folding of multi-line log entries - available on log entry header lines.
  2. Folding of indented structures (like context dumps, operation result dumps etc) - available at each indentation level.
  3. Folding of profiling entry/exit pairs: Some operations (like getObject in provisioning) may take hundreds of log lines. By clicking on 'collapse' button of particular "#### Entry" line everything gets collapsed up to corresponding "##### Exit" line.

An example of indented structure folding (hiding user old & current, keeping user new):

An example of collapsed entry-exit pair #74 (provisioning getObject call):

Folding can be also done declaratively. E.g. we could tell Log Viewer to automatically collapse all log entries related to ResourceManager:

Or collapse all profiling information related to calls Provisioning->getObject:

Complete syntax

Collapses or expands given line or whole entry. (Actually, collapse-entry can be written also as collapse-line, when the line in question is entry header one. However, distinguishing between the two leads to easier understanding.)

Permanently removing unnecessary lines

Sometimes there are lines that clutter the log and we know we won't need them any more. We can delete them using %kill instruction, like this:

The algorithm to remove individual lines can be improved - in current state killing many lines in large files can take a quite long time (minutes).

Complete syntax

Kills given lines or whole entries.

Objects and threads dictionary

Log viewer scans through the log file and automatically extracts a list of known objects as well as a list of threads. It looks like this:

Each line contains an OID, object type (e.g. account), name (e.g. elaine) and color in which this OID has to be displayed (default). Name and color can be edited. This information is used to highlight these OID in the logfile, as well as to show object name by hovering the cursor over object OID in log file text.

And for threads:

This is fine for quick orientation, and for selection which threads should be included in/excluded from the outline, or even removed from the logfile completely.

OID highlighting and associated information display

As described above, log viewer displays OIDs in bold fond, and optionally with a different color.

For example, if we would like to trace occurrences of jack and barbossa, we could tell Log Viewer to display their OIDs in red and blue, respectively:

Then the log could look like this:

...giving immediate visual information useful to quickly recognize relevant objects in the log file.

Also, when encountering unknown OID, you can just hover the cursor over it, and you'll see the type and name of particular object (if known):

Logfile preprocessing: LogTrimmer tool

Large log files are awkward to process in test editors, especially in complex ones like Eclipse editor. So it may be useful to preprocess them by removing unimportant information.

LogTrimmer tool has the following usage:

Where:

  1. instructions-file contains instructions that have to be carried out on the input
  2. input-file-1..N are input files; there can be more of them because large logs are usually split into smaller parts (~ 100 MB each)
  3. output-file is the name of resulting file - merged and processed input ones

Currently there are the following instructions available:

First one (trim) is used to shorten selected log entries. "Lines to keep" is the number of lines that should be kept from the log entry. Examples:

Second one (select-test) is used to preserve only given test (from a log that contains a set of tests). Example:

TODO - use similar definition language as in Log Viewer (e.g. %kill instruction).

Logfile erasing: Truncater tool

On MS Windows systems it is quite hard to truncate open files. There is a PowerShell command to do that:

...but on systems without PowerShell there is this Truncater tool to do the same:

Installation

The log viewer is now part of Eclipse plugin. For installation instructions, please see Eclipse plugin installation HOWTO.

Note: when working with any non-trivial log files, increase the heap for Eclipse to at least 2 GB. The larger files, the bigger heap is required. Also, obtain appropriately fast CPU (smile)

Use

First, create an empty project in Eclipse. Then copy a log file to it (recommended is to create a subfolder if there would be more log files viewed). Note that log files have to have .log suffix to be recognizable.

Now open the file in Eclipse log viewer by choosing Open With -> Evolveum Log Viewer:

When a log file is first opened, OID and threads dictionary is created, and default configuration is appended to the file. You'll see that the file is marked as "modified". It is advisable to save the file at this point. (E.g. for OID name display to work.)

Now you can work with the file.

Notes:

  1. The outline is not updated automatically. So, if you edit the file (or change outline definitions), always save the file afterwards. Save causes recomputation of the outline.
  2. Because building outline, setting regions, etc is quite time-consuming, selected actions - namely, application of %kill, %expand, %collapse instructions and color highlighting of OIDs - can be invoked by selecting "Apply Evolveum Log Viewer Configuration" from editor context menu (or pressing ALT+F3).
  3. In order to see errors/warnings/infos only from the currently open file, it is advisable to configure Problems view to include markers on selected element only:

Performance tuning

Log viewer is a powerful tool to find certain classes of performance problems. To ensure completeness of the data it is advised to have only following class loggers in logging configuration:

Other class loggers of type com.evolveum.midpoint.model.* should be removed from systems configuration as they would interfere with com.evolveum.midpoint.model classLogger.

Concluding remark

This plugin is currently just a prototype. It may or may not work as expected. We would be grateful for any comments, suggestions, or error reports.

 

  • No labels