Post processing trace statements.

 

After doing log analysis for a project for a while you will start identifying the key trace statements. These are statements that you will search in most of your logs. If you are using my log analyzer (log parser)  tool your will have a rule for each of the key trace statements.

   You will also notice that some of those statements are not “user friendly”. Maybe they report the execution of a function or method. Or provide too much information. Or you just don’t like the words being used.

    At the end of the day your index could have entries like these:

 1385 -> Apr 8 16:55:15 MiniPaquina : Kernel::Boot( 3.0.0-17-generic).

 1834 -> SNR: sBlock.getState() = 1

 5014 -> 15.219.169.69 – - [04/Apr/2012:18:51:27 -0700] “GET /downloads/LogAnalyzer.zip HTTP/1.1″ 200 5555533 “-” “Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.1; WOW64; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0; InfoPath.2)”

   But you will prefer to “change” them to something like:

 1385 -> Turning on at Apr 8 16:55:15.

 1834 -> Obstacle ahead !

 5014 -> Downloading: LogAnalyzer.zip

   The best way to make this happen is to change the trace statements on the source code. Unfortunately this in not always possible. Maybe because you are not the owner of that component or because the statement is generated automatically or because it is safer to report all the information and allow the user of the log to select the relevant portion.

    An alternative for this cases (if you are using the log analyzer) is to use the “format” element of each rule to create your own output that combines portions of the original line with your own strings. Lets explore this option with an example.

   If the line to find is:

 5014 -> 15.219.169.69 – - [04/Apr/2012:18:51:27 -0700] “GET /downloads/LogAnalyzer.zip HTTP/1.1″ 200 5555533 “-” “Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.1; WOW64; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0; InfoPath.2)”

   And the patterns are:

 [- - []

["] GET /downloads/]

[HTTP/]

    Then the variables are:

 <$0> = [15.219.169.69]

<$1> = [04/Apr/2012:18:51:27 -0700]

<$2> = [LogAnalyzer.zip]

<$3> = [.1" 200 5555533 "-" "Mozilla/4.0 ...]

    If we define the format as:

 Download <$2> to <$0> at <$1>.

    The index will show:

 5014 -> Download LogAnalyzer.zip to 15.219.169.69 at 04/Apr/2012:18:51:27 -0700

    Now lets take a closer look to the format field:

  • Strings outside of <> will be printed directly to the output.

  • Strings with <$n> format will be replaced with contents of variable n.

   You can learn more about the log parser (or log analyzer) or even download if for a 30 day free trial and try this method.

Start Analyzing your first log in less than 10 minutes.

   The first thing I did before sharing my log analyzer (or log parser)   with coworkers was writing a manual. I honestly thought I did a decent job with it. But as soon as I started answering questions from users I discovered that NOBODY READ MY MANUAL!

   I had to be honest with myself and recognize that I don’t read the manuals either because I prefer to learn by doing than by reading. So I’ve written short guide that will have you doing log analysi with my tool in less than 10 minutes.

 

Definitions.

   The log parser has three main components:

  1. Log Viewer: Displays a section of the original log file. (Upper right)
  2. Rule Set: Manages the rules available to analyze the log. (Left)
  3. Index: Provides an ordered list of the rule matches found on the log. (Lower right)

   Rules are the key element of the log analyzer. When a rule is applied to a log file each
line of the log file will be tested against it. For each line that contains all the rule
patterns a new match is added to the index.

   A rule has the following elements:

  1. Name: Unique identifier for each rule.
  2. Example: A line of text that matches the rule criteria.
  3. Patterns: A list of strings that must be present on a log line for the rule to match.
  4. Variables: A list of strings “trapped” between patterns on lines that match.
  5. Format: How a match will be added to the index.

   Match index can be used to browse through the log file or exported to document
the signature of the defect.

Initial Steps.

   In order to use the log analyzer to perform log analysis for the first time, please execute the following steps:

   1. Open a log file. [Log->Load]

  • If you don’t see your log change the extension filter to all
  • Recommended file extension is “.rls”.
  • Title will show: (L =<filename>, R = None) … 0/<lines>.
  • Viewer will show the first 1000 lines of the log.

2. Create a rule set. [Rules -> New Set]

  • This file will store all the rules you will create later.
  • Title changes to: (L =<filename>, R = <RuleSet>) … 0/<file lines>.
  • You can create a rule per project or per issue.

3. Find a line of interest.

  • To search for a string use [Log->Find].
  • To find the next line with the same string [Log->Next]
  • To find the previous line with the same string [Log->Previous]
  • You can find the current line number at the end of the title
  • (L =<filename>, R = <RuleSet>) … <current line>/<file lines>])

4.Create a rule for the line of interest. <Double click on it>

  • A “Rule Constructor” dialog will open for you.
  • The line of interest will be in the Example field.

5. Name the rule. (Will help you identify the rule latter)

6. Add rule patterns:

  • All patterns must be present in a text line to be a rule match.
  • Highlight a constant portion of the example line and press the
    <Add Pattern> button.
  • Add as many rule patterns as needed.
  • Text between patterns will automatically be added to the variable list.

7. Define the match format.

  • Format defines how the match will show up in the index.
  • It can be a mix of text and variables.
  • To print a variable add <$n> to the format.
  • If you leave the format field empty matching lines will be added to the index without modifications.

8. Save the rule [Press the <Ok> button]

  • Your new rule will be listed in the set at the left side.

9. Apply the rule to the log file. [Double click on the rule name.

  • All matches for that rule will be added to the index.

10. Go back to step 3 to add/execute as many rules as needed.

11. Explore index..

  • Double click on the match.
  • Use the log viewer scroll bar as needed.

12. Copy the index as text to document issue or share with partners. [Index->Copy All]

Executing this steps should allow you to do your first log analysis quickly and get an
idea of how the log analyzer (or log parser) works. If this is enough for you great. If you would like to
learn more about the available options please read this tool’s manual.

What to log?

Print (or trace) debugging is the act of watching (live or recorded) trace statements, or print statements, that indicate the flow of execution of a process. This is sometimes called printf debugging, due to the use of the printf statement in C. This kind of debugging was turned on by the command TRON in the original versions of the novice-oriented BASIC programming language. TRON stood for, “Trace On.” TRON caused the line numbers of each BASIC command line to print as the program ran.

After more than 10 years of using logs to triage defects on my software I’ve identified two key elements to make this technique efficient:

  1. Selecting the trace statements wisely.
  2. Having a good method to analyze the logs.

Read the rest of this entry »

Is printf debugging obsolete?

According to wikipedia debugging is a methodical process of finding and reducing the number of bugs, or defects, in a computer program or a piece of electronic hardware, thus making it behave as expected.

The most popular technique is to use a debugger. A debugger is a computer program that is used to test and debug other programs (the “target” program). Typically, debuggers offer functions such as running a program step by step (single-stepping or program animation), stopping (breaking) (pausing the program to examine the current state) at some event or specified instruction by means of a breakpoint, and tracking the values of variables. Some debuggers have the ability to modify program state while it is running. It may also be possible to continue execution at a different location in the program to bypass a crash or logical error.

Using a debugger is a very powerful and popular debugging method, but it is not the best option for all cases. You might be triaging software that controls hardware. And hitting a break point at the wrong moment might damage that hardware (I’ve burned a motor this way). Or you might be trying to understand a failure that happened while the debugger was not attached.

A very simple alternative for these cases is to use print debugging. Print (or trace) debugging is the act of watching (live or recorded) trace statements, or print statements, that indicate the flow of execution of a process. This is sometimes called printf debugging, due to the use of the printf statement in C. This kind of debugging was turned on by the command TRON in the original versions of the novice-oriented BASIC programming language. TRON stood for, “Trace On.” TRON caused the line numbers of each BASIC command line to print as the program ran.

As an embedded software developer I typically combine both techniques:

  1. I analyze the logs captured during product testing in order to find the steps to to reproduce the failure at my desk.
  2. Then I use a debugger to step trough the failure and find the root cause.

After more than 10 years of using logs to triage defects on my software I’ve identified two key elements to make this technique efficient:

  1. Selecting the trace statements wisely.
  2. Having a good log analysis method.

Defining the trace statements is a balancing act. On one side you want to add as few messages as possible to reduce the performance impact and keep the size of the logs manageable. But at the same time you want to make enough statements to understand  all the potential bugs. There are several tricks to help with the selection: like separating the trace statements in to channels, making the trace level configurable at run time, or generating encoded logs that will be expanded before analyzing them. I will talk more about this on a separate post. For now I would just like to point out that it is an ongoing effort that will continue until the end of the project. So start with your best guess and then add and delete statements as needed.

Having a good log analysis method  is as important as having the right trace statements. Having the information in the log will not help you unless you are able to “find the clues”. And since the defect fixing phase of a project can last for months it is important to do it as efficiently as possible. Specially if you still pretend to have a life after work ;^).

The procedure I developed over time was:

  1. Open the log with my favourite text editor.
  2. Use its search features to locate the relevant strings.
  3. Add an extra line with my comments at each key point.
  4. Use grep to extract all my comments and create an index.
  5. Use the index to document the failure mode and navigate trough the log.

The disadvantages of this process were:

  1. You need to remember and type each one of the key strings you want to search.
  2. You modify the original log by adding your comments.
  3. You have to work with several files “at the same time”. (I ended up having the log file, the index file and my common strings to search file)

I finally got tired of this error prone and labor intensive process and started looking for a way to automate it. I did a web search and found lots of tools. But none of them satisfied my needs. The main problems with those log analyzers or log parsers  where:

  • They were designed for a specific type of logs (like the web server logs) and where not easy to adapt to my software output.
  • They will perform the log analysis  to produce a report with statistic information.

What I needed was a generic log analyzer (or log parser) but I couldn’t find it. So I finally decided to creating my own log analysis tool at home as a hobby. When I started using my log analyzer at work I noticed that it reduced my analysis time by half while increasing the accuracy of my results. So I started sharing the tools with my coworkers who also found it useful.

That is why I’ve decided to publish my log parser tool online hoping it can be useful to other developers who might be looking for a better log analysis option. Please feel free to learn more about my log analyzer  (or log parser) and/or download it for a free 30 day period trial.