Gem #114: Logging with GNATCOLL.Traces

Let’s get started …

When we write applications, we often add Put_Line statements to help debug the initial version of the code. Once that code works, we remove the Put_Line and move on to some other feature of the code. The problem is that when a bug occurs again in that part of the code (and especially when this is reported by a user and you can’t debug on his machine), the output would still be useful, but it’s no longer present in the executable.

The solution, of course, is to output the traces to some “log” file, and keep the traces forever in the code. The log file will eventually become very large if you have lots of traces, and finding information there might not be so easy. So, a better solution is to split the traces into various groups, and have a capability to display only some of the groups, so as to limit the amount of information to look at.

The GNAT Components Collection includes a package GNATCOLL.Traces that provides support for this. This package is used in various AdaCore products, in particular GPS.

The first thing to do is to initialize the module. The traces are configured via an external file, which by default is called “.gnatdebug”, and is searched for in the current directory.

   with GNATCOLL.Traces;   use GNATCOLL.Traces;
   with User;
   procedure Main is
   begin
      Parse_Config_File;   --  parses default ./.gnatdebug
      User.Proc;
   end Main;

The simplest way to compile this code is to use a project file. For instance:

with "gnatcoll";
project Default is
    for Main use ("main.adb");
end Default;

gprbuild -Pdefault.gpr

In the rest of the code we can create a stream. All log messages are sent to a stream, and you are free to create as many as you want. A log message will always be prefixed by the name of its stream, as a way to organize traces in the log file. Here is what the Ada code would look like:

package User is
   Stream1 : constant Trace_Handle := Create ("Stream1");

   procedure Proc is
   begin
      Trace (Stream1, "Some trace");
   end Proc;
end User;

If you compile this code and run it, there will in fact be nothing logged. That’s because the trace streams are disabled by default. We thus need to create a configuration file. Its format is very simple. The following example demonstrates a number of its features:

+
> log
TRACE1=yes
TRACE2=no
TRACE3=yes > log2
DEBUG.COLORS=yes

The first line (“+”) indicates that we would like to activate all the streams by default. So a file with only that line would already show the output in our Ada example.

The second line (“>log”) indicates where the output of the streams should go by default. If this isn’t specified, the output goes to stdout. Otherwise, you can specify a file name. Advanced usage allow you to define other types of redirection. For instance, GNATCOLL comes by default with support for redirecting to syslog on Unix systems. It would be relatively simple to add support for custom outputs, like a socket, a database, etc.

The next three lines configure specific streams and show how to activate or disable them. The fifth line, in particular, redirects one of the streams to another log file.

The last line in the example activates one of the extra features of GNATCOLL.Traces. Activating “DEBUG.COLORS” will output the stream using different colors for the various information that is output on each line.

Other facilities are available. For instance, if you activate “DEBUG.ABSOLUTE_TIME”, each line in the log file will include the time of the message. More powerfully, you can activate “DEBUG.STACK_TRACE” to get a stack trace for each message (note that the trace needs to be converted via addr2line). Another useful one is “DEBUG.COUNT”, which will add the number of messages output so far in total and for the specific stream.

Here is what the log file will look like:

[STREAM1] 1/1 Some Trace (09:05:32.323)
[STREAM4] 1/2 Some Other Trace (09:05:33.125)

As we have seen in the example, text is output using the Trace function. There are two versions of it: the one we saw that is used to output a simple message, and another version that takes an exception occurrence as a parameter and outputs information about that exception. There is also a procedure called Assert that will output an error message if a Condition is False. The error will be displayed in red if the colors were activated, thus making it easy to locate in the log file.

Preparing the text for a message might be expensive (for instance, if the text should contain the result of a function call, or requires a lot of string concatenation). For this, the recommended coding pattern is:

   if Active (Stream1) then
      Trace (Stream1, "Function result was " & Func(...));
   end if;

The log file might still be hard to read when it gets big. GNATCOLL.Traces provides a facility for indenting the traces. Here is a full example of code computing Fibonacci numbers recursively:

pragma Ada_05;
with Ada.Text_IO;       use Ada.Text_IO;
with GNATCOLL.Traces;   use GNATCOLL.Traces;

procedure Fibo is
   Me : constant Trace_Handle := Create ("FIBO");

   function Recurse (Num : Positive) return Positive is
      Result : Integer;
   begin
      if Num = 1 or else Num = 2 then
         return 1;
      end if;

      Increase_Indent (Me, "Computing" & Num'Img);
      Result := Recurse (Num - 1) + Recurse (Num - 2);
      Decrease_Indent (Me, "Done =>" & Result'Img);
      return Result;
   end Recurse;

begin
   Parse_Config_File;
   Put_Line (Recurse (5)'Img);
end Fibo;

The code should be compiled with a project file, as shown earlier. The current directory should also contain a file called “.gnatdebug” with a single line that contains “+”. The output on stdout is:

[FIBO] 1/1 Computing 5
   [FIBO] 2/2 Computing 4
      [FIBO] 3/3 Computing 3
      [FIBO] 4/4 Done => 2
   [FIBO] 5/5 Done => 3
   [FIBO] 6/6 Computing 3
   [FIBO] 7/7 Done => 2
[FIBO] 8/8 Done => 5
 5

which shows the indentation that is increased for each recursive call.

GNATCOLL.Traces uses object-oriented code. It provides a number of hooks through which you can add your own extra data each time some line is output to the log file. For this, you should override the Pre_Decorator or Post_Decorator primitive operations.