4. Traces: Logging information

Most applications need to log various kinds of information: error messages, information messages or debug messages among others. These logs can be displayed and stored in a number of places: standard output, a file, the system logger, an application-specific database table,…

The package GNATCOLL.Traces addresses the various needs, except for the application-specific database, which of course is specific to your business and needs various custom fields in any case, which cannot be easily provided through a general interface.

This module is organized around two tagged types (used through access types, in fact, so the latter are mentioned below as a shortcut):

Trace_Handle

This type defines a handle (similar to a file descriptor in other contexts) which is latter used to output messages. An application will generally define several handles, which can be enabled or disabled separately, therefore limiting the amount of logging.

Trace_Stream

Streams are the ultimate types responsible for the output of the messages. One or more handles are associated with each stream. The latter can be a file, the standard output, a graphical window, a socket,… New types of streams can easily be defined in your application.

4.1. Configuring traces

As mentioned above, an application will generally create several Trace_Handle (typically one per module in the application). When new features are added to the application, the developers will generally need to add lots of traces to help investigate problems once the application is installed at a customer’s site. The problem here is that each module might output a lot of information, thus confusing the logs; this also does not help debugging.

The GNATCOLL.Traces package allows the user to configure which handles should actually generate logs, and which should just be silent and not generate anything. Depending on the part of the application that needs to be investigated, one can therefore enable a set of handles or another, to be able to concentrate on that part of the application.

This configuration is done at two levels:

  • either in the source code itself, where some trace_handle might be disabled or enabled by default. This will be described in more details in later sections.

  • or in a configuration file which is read at runtime, and overrides the defaults set in the source code.

The configuration file is found in one of three places, in the following order:

  • The file name is specified in the source code in the call to Parse_Config_File.

  • If no file name was specified in that call, the environment variable ADA_DEBUG_FILE might point to a configuration file.

  • If the above two attempts did not find a suitable configuration file, the current directory is searched for a file called .gnatdebug. Finally, the user’s home directory will also be searched for that file.

In all cases, the format of the configuration file is the same. Its goal is to associate the name of a trace_handle with the name of a trace_stream on which it should be displayed.

Streams are identified by a name. You can provide additional streams by creating a new tagged object (Defining custom stream types). Here are the various possibilities to reference a stream:

“name”

where name is a string made of letters, digits and slash (‘/’) characters. This is the name of a file to which the traces should be redirected. The previous contents of the file is discarded. If the name of the file is a relative path, it is relative to the location of the configuration file, not necessarily to the current directory when the file is parsed. In the file name, $$ is automatically replaced by the process number. $D is automatically replaced by the current date. $T is automatically replaced by the current date and time. Other patterns of the form $name, ${name}, or $(name) are substituted with the value of the named environment variable, if it exists. If “>>” is used instead of “>” to redirect to that stream, the file is appended to, instead of truncated.

“&1”

This syntax is similar to the one used on Unix shells, and indicates that the output should be displayed on the standard output for the application. If the application is graphical, and in particular on Windows platforms, it is possible that there is no standard output!

“&2”

Similar to the previous one, but the output is sent to standard error.

“&syslog”

Logging to syslog.

Comments in a configuration file must be on a line of their own, and start with –. Empty lines are ignored. The rest of the lines represent configurations, as in:

  • If a line contains the single character “+”, it activates all trace_handle by default. This means the rest of the configuration file should disable those handles that are not needed. The default is that all handles are disabled by default, and the configuration file should activate the ones it needs. The Ada source code can change the default status of each handles, as well

  • If the line starts with the character “>”, followed by a stream name (as defined above), this becomes the default stream. All handles will be displayed on that stream, unless otherwise specified. If the stream does not exist, it defaults to standard output.

  • Otherwise, the first token on the line is the name of a handle. If that is the only element on the line, the handle is activated, and will be displayed on the default stream.

    Otherwise, the next element on the line should be a “=” sign, followed by either “yes” or “no”, depending on whether the handle should resp. be enabled or disabled.

    Finally, the rest of the line can optionally contain the “>” character followed by the name of the stream to which the handle should be directed.

    There is are two special cases for the names on this line: they can start with either “*.” or “.*” to indicate the settings apply to a whole set of handles. See the example below.

Here is a short example of a configuration file. It activates all handles by default, and defines four handles: two of them are directed to the default stream (standard error), the third one to a file on the disk, and the last one to the system logger syslog (if your system supports it, otherwise to the default stream, ie standard error):

+
>&2
MODULE1
MODULE2=yes
SYSLOG=yes >&syslog:local0:info
FILE=yes >/tmp/file

--  decorators (see below)
DEBUG.COLORS=yes

--  Applies to FIRST.EXCEPTIONS, LAST.EXCEPTIONS,...
--  and forces them to be displayed on stdout
*.EXCEPTIONS=yes > stdout

--  Applies to MODULE1, MODULE1.FIRST,... This can be used to
--  disable a whole hierarchy of modules.
--  As always, the latest config overrides earlier ones, so the
--  module MODULE1.EXCEPTIONS would be disabled as well.

MODULE1.*=no

4.2. Using the traces module

If you need or want to parse an external configuration file as described in the first section, the code that initializes your application should contain a call to GNATCOLL.Traces.Parse_Config_File. As documented, this takes in parameter the name of the configuration file to parse. When none is specified, the algorithm specified in the previous section will be used to find an appropriate configuration:

GNATCOLL.Traces.Parse_Config_File;

The code, as written, will end up looking for a file .gnatdebug in the current directory.

The function Parse_Config_File must be called to indicate that you want to activate the traces. It must also end up finding a configuration file. If it does not, then none of the other functions will ever output anything. This is to make sure your application does not start printing extra output just because you happen to use an external library that uses GNATCOLL.Traces. It also ensures that your application will not try to write to stdout unless you think it is appropriate (since stdout might not even exist in fact).

You then need to declare each of the trace_handle (or logger) that your application will use. The same handle can be declared several times, so the recommended approach is to declare locally in each package body the handles it will need, even if several bodies actually need the same handle. That helps to know which traces to activate when debugging a package, and limits the dependencies of packages on a shared package somewhere that would contain the declaration of all shared handles.

Function Trace_Handle Create Name Default Stream Factory Finalize

This function creates (or return an existing) a trace_handle with the specified Name. Its default activation status can also be specified (through Default), although the default behavior is to get it from the configuration file. If a handle is created several times, only the first call that is executed can define the default activation status, the following calls will have no effect.

Stream is the name of the stream to which it should be directed. Here as well, it is generally better to leave things to the configuration file, although in some cases you might want to force a specific behavior.

Factory is used to create your own child types of trace_handle (Log decorators).

Here is an example with two package bodies that define their own handles, which are later used for output:

package body Pkg1 is
   Me : constant Trace_Handle := Create ("PKG1");
   Log : constant Trace_Handle := Create ("LOG", Stream => "@syslog");
end Pkg1;

package body Pkg2 is
   Me : constant Trace_Handle := Create ("PKG2");
   Log : constant Trace_Handle := Create ("LOG", Stream => "@syslog");
end Pkg2;

Once the handles have been declared, output is a matter of calling the GNATCOLL.Traces.Trace procedure, as in the following sample:

Trace (Me, "I am here");

An additional subprogram can be used to test for assertions (pre-conditions or post-conditions in your program), and output a message whether the assertion is met or not:

Assert (Me, A = B, "A is not equal to B");

If the output of the stream is done in color, a failed assertion is displayed with a red background to make it more obvious.

4.2.1. Logging unexpected exceptions

A special version of Trace is provided, which takes an Exception_Occurrence as argument, and prints its message and backtrace into the corresponding log stream.

This procedure will in general be used for unexcepted exceptions. Since such exceptions should be handled by developers, it is possible to configure GNATCOLL.TRACES to use special streams for those.

Trace (Me, E) will therefore not used Me itself as the log handle, but will create (on the fly, the first time) a new handle with the same base name and and .EXCEPTIONS suffix. Therefore, you could put the following in your configuration file:

# Redirect all exceptions to stdout
*.EXCEPTIONS=yes >& stdout

and then the following code will output the exception trace to stdout:

procedure Proc is
   Me : Create ("MYMODULE");
begin
   ...
exception
   when E : others =>
      Trace (Me, E, Msg => "unexcepted exception:");
end Proc;

4.2.2. Checking whether the handle is active

As we noted before, handles can be disabled. In that case, your application should not spend time preparing the output string, since that would be wasted time. In particular, using the standard Ada string concatenation operator requires allocating temporary memory. It is therefore recommended, when the string to display is complex, to first test whether the handle is active. This is done with the following code:

if Active (Me) then
   Trace (Me, A & B & C & D & E);
end if;

4.3. Log decorators

Speaking of color, a number of decorators are defined by GNATCOLL.Traces. Their goal is not to be used for outputting information, but to configure what extra information should be output with all log messages. They are activated through the same configuration file as the traces, with the same syntax (i.e either “=yes” or “=no”).

Here is an exhaustive list:

DEBUG.ABSOLUTE_TIME

If this decorator is activated in the configuration file, the absolute time when Trace is called is automatically added to the output, when the streams supports it (in particular, this has no effect for syslog, which already does this on its own).

DEBUG.MICRO_TIME

If active, the time displayed by DEBUG.ABSOLUTE_TIME will use a microseconds precision, instead of milliseconds.

DEBUG.ELAPSED_TIME

If this decorator is activated, then the elapsed time since the last call to Trace for the same handle is also displayed.

DEBUG.STACK_TRACE

If this decorator is activated, then the stack trace is also displayed. It can be converted to a symbolic stack trace through the use of the external application addr2line, but that would be too costly to do this automatically for each message.

DEBUG.LOCATION

If this decorator is activated, the location of the call to Trace is automatically displayed. This is a file:line:column information. This works even when the executable wasn’t compiled with debug information

DEBUG.ENCLOSING_ENTITY

Activate this decorator to automatically display the name of the subprogram that contains the call to Trace.

DEBUG.COLORS

If this decorator is activated, the messages will use colors for the various fields, if the stream supports it (syslog doesn’t).

DEBUG.COUNT

This decorator displays two additional numbers on each line: the first is the number of times this handle was used so far in the application, the second is the total number of traces emitted so far. These numbers can for instance be used to set conditional breakpoints on a specific trace (break on gnat.traces.log or gnat.traces.trace and check the value of Handle.Count. It can also be used to refer to a specific line in some comment file.

DEBUG.MEMORY

Every time a message is output, display the amount of memory currently in use by the application.

DEBUG.SPLIT_LINES

When this is enabled, messages are split at each newline character. Each line then starts with the name of the logger, indentation level and so on. This might result in more readable output, but is slightly slower.

DEBUG.FINALIZE_TRACES

This handle is activated by default, and indicates whether GNATCOLL.Traces.Finalize should have any effect. This can be set to False when debugging, to ensure that traces are available during the finalization of your application.

Here is an example of output where several decorators were activated. In this example, the output is folded on several lines, but in reality everything is output on a single line:

[MODULE] 6/247 User Message (2007-07-03 13:12:53.46)
   (elapsed: 2ms)(loc: gnatcoll-traces.adb:224)
   (entity:GNATCOLL.Traces.Log)
   (callstack: 40FD9902 082FCFDD 082FE8DF )

Depending on your application, there are lots of other possible decorators that could be useful (for instance the current thread, or the name of the executable when you have several of them,…). Since GNATCOLL.Traces cannot provide all possible decorators, it provides support, through tagged types, so that you can create your own decorators.

This needs you to override the Trace_Handle_Record tagged type. Since this type is created through calls to GNATCOLL.Traces.Create. This is done by providing an additional Factory parameter to Create; this is a function that allocates and returns the new handle.

Then you can override either (or both) of the primitive operations Pre_Decorator and Post_Decorator. The following example creates a new type of handles, and prints a constant string just after the module name:

type My_Handle is new Trace_Handle_Record with null record;
procedure  Pre_Decorator
  (Handle  : in out My_Handle;
   Stream  : in out Trace_Stream_Record'Class;
   Message : String) is
begin
   Put (Stream, "TEST");
   Pre_Decorator (Trace_Handle_Record (Handle), Stream, Message);
end**;

function Factory return Trace_Handle is
begin
   return new My_Handle;
end;

Me : Trace_Handle := Create ("MODULE", Factory => Factory'Access);

As we will see below (Dynamically disabling features), you can also make all or part of your decorators conditional and configurable through the same configuration file as the trace handles themselves.

4.4. Defining custom stream types

We noted above that several predefined types of streams exist, to output to a file, to standard output or to standard error. Depending on your specific needs, you might want to output to other media. For instance, in a graphical application, you could have a window that shows the traces (perhaps in addition to filing them in a file, since otherwise the window would disappear along with its contents if the application crashes); or you could write to a socket (or even a CORBA ORB) to communicate with another application which is charge of monitoring your application.

You do not need the code below if you simply want to have a new stream in your application (for instance using one for logging Info messages, one for Error messages, and so on). In this case, the function Create is all you need.

GNATCOLL.Traces provides the type Trace_Stream_Record, which can be overridden to redirect the traces to your own streams.

Let’s assume for now that you have defined a new type of stream (called “mystream”). To keep the example simple, we will assume this stream also redirects to a file. For flexibility, however, you want to let the user configure the file name from the traces configuration file. Here is an example of a configuration file that sets the default stream to a file called foo, and redirects a specific handle to another file called bar. Note how the same syntax that was used for standard output and standard error is also reused (ie the stream name starts with the “&” symbol, to avoid confusion with standard file names):

>&mystream:foo
MODULE=yes >&mystream:bar

You need of course to do a bit of coding in Ada to create the stream. This is done by creating a new child of Trace_Stream_Record, and override the primitive operation Put.

The whole output message is given as a single parameter to Put:

type My_Stream is new Trace_Stream_Record with record
   File : access File_Type;
end record;

procedure Put
  (Stream : in out My_Stream; Str : Msg_Strings.XString)
is
   S : Msg_Strings.Unconstrained_String_Access;
   L : Natural;
begin
   Str.Get_String (S, L);
   Put (Stream.File.all, String (S (1 .. L)));
end Put;

The above code did not open the file itself, as you might have noticed, nor did it register the name “mystream” so that it can be used in the configuration file. All this is done by creating a factory, ie a function in charge of creating the new stream.

A factory is also a tagged object (so that you can store custom information in it), with a single primitive operation, New_Stream, in charge of creating and initializing a new stream. This operation receives in parameter the argument specified by the user in the configuration file (after the “:” character, if any), and must return a newly allocated stream. This function is also never called twice with the same argument, since GNATCOLL.Traces automatically reuses an existing stream when one with the same name and arguments already exists:

type My_Stream_Factory is new Stream_Factory with null record;

overriding function New_Stream
   (Self : My_Stream_Factory; Args : String) return Trace_Stream
is
   Str : access My_Stream := new My_Stream;
begin
   Str.File := new File_Type;
   Open (Str.File, Out_File, Args);
   return Str;
end Factory;

Fact : access My_Stream_Factory := new My_Stream_Factory;
Register_Stream_Factory ("mystream", Fact);

4.5. Logging to syslog

Among the predefined streams, GNATColl gives access to the system logger syslog. This is a standard utility on all Unix systems, but is not available on other systems. When you compile GNATColl, you should specify the switch –enable-syslog to configure to activate the support. If either this switch wasn’t specified, or configure could not find the relevant header files anyway, then support for syslog will not be available. In this case, the package GNATCOLL.Traces.Syslog is still available, but contains a single function that does nothing. If your configuration files redirect some trace handles to “syslog”, they will instead be redirect to the default stream or to standard output.

Activating support for syslog requires the following call in your application:

GNATCOLL.Traces.Syslog.Register_Syslog_Stream;

This procedure is always available, whether your system supports or not syslog, and will simply do nothing if it doesn’t support syslog. This means that you do not need to have conditional code in your application to handle that, and you can let GNATColl take care of this.

After the above call, trace handles can be redirected to a stream named “syslog”.

The package GNATCOLL.Traces.Syslog also contains a low-level interface to syslog, which, although fully functional, you should probably not use, since that would make your code system-dependent.

Syslog itself dispatches its output based on two criteria: the facility, which indicates what application emitted the message, and where it should be filed, and the level which indicates the urgency level of the message. Both of these criteria can be specified in the GNATCOLL.Traces configuration file, as follows:

MODULE=yes >&syslog:user:error

The above configuration will redirect to a facility called user, with an urgency level error. See the enumeration types in gnatcoll-traces-syslog.ads for more information on valid facilities and levels.

4.6. Dynamically disabling features

Although the trace handles are primarily meant for outputting messages, they can be used in another context. The goal is to take advantage of the external configuration file, without reimplementing a similar feature in your application. Since the configuration file can be used to activated or de-activated a handle dynamically, you can then have conditional sections in your application that depends on that handle, as in the following example:

CONDITIONAL=yes

and in the Ada code:

package Pkg is
   Me : constant Trace_Handle := Create ("CONDITIONAL");
begin
   if Active (Me) then
      ... conditional code
   end if;
end Pkg;

In particular, this can be used if you write your own decorators, as explained above.