Logging - Monod

Next: Simulation-Specific Algorithms, Previous: Architecture, Up: Implementation Details

7.5 Logging

Logging is a cross-cutting aspect of the implementation of Monod. Logging messages are distributed throughout the source code. Depending on compile-time and run-time variables, the messages are streamed to a specified output as the program is executed. It's very much like spreading print statements through the code, but in a more controlled fashion.

The log messages are output to the file monod.log located where the executable is launched. FIXME: change the output using a command-line option and rotate the output files.

Log messages have the following components:

A logging level, described below;
A thread number, indicating the thread ID of the thread issuing the message;
A time stamp, valid up to the second;
The filename of the source file containing the message;
The line number of the message is the source file;
The message-specific contents.

All of these components are easily identifiable in the output. An example is shown below.

     *** Info *** for thread 5 at 10/2 05:32:42 in swarm.ml line 387
     Runner thread blocking
     *** Info *** for thread 6 at 10/2 05:32:42 in swarm.ml line 423
     Matcher thread waking up
     *** Exec *** for thread 6 at 10/2 05:32:42 in swarm.ml line 178
     Entering calculate_all_matches
     *** Exec *** for thread 6 at 10/2 05:32:42 in incubator.ml line 434
     Calculating the full marker for a procunit
     *** Data *** for thread 6 at 10/2 05:32:42 in incubator.ml line 445
     Procunit marker is matcher "BBB"

Each message consists of two lines, with the contents appearing on the second line.

The log levels are simply an ordered set of names which indicate the importance of a message. There are 11 possible log levels. Along with a description of their meaning, they are:

Emerg: This event needs a human intervention to recover. The entire system is compromised and execution is aborted.
Alert: Something went wrong and at least one thread of execution was not recovered.
Error: Recovered error. Needs investigation.
Warning: Something is fishy. Needs investigation.
Exceptional: A secondary code flow.
Config: Configuration setup of change.
User: Used-invoked alteration.
Info: Informational message. Something significant has happened.
Exec: Tracing the execution flow.
Debug: Debugging information.
Data: Parameter dumps.

The log level names which appear above can be passed as the parameter to the --log-level command-line argument, as described in Command-line Arguments (capitalization is important). When set to a certain level, only those messages which have an importance at least equal to that level will be output. Currently, the default log level for all Monod executables is Warning.

To add log messages to the source code, simply write a single line of the form

     LOG <level> "Message to log; %s is a string variable" astring;

where level is one of the levels given above, and the message can be anything, including standard printf arguments. However, the message must be contained on a single line and end with a semicolon.

All source files are pre-processed with a Perl script, logifier.pl, which is located in the main directory. This script replaces all occurrences of the LOG keyword with the appropriate (and optimized) OCaml code. The Perl script is too simple to process multi-line messages.

The logging level has a very significant impact on the performance of Monod, to the point where certain tests can fail depending on the log level. For instance, the Incubator-layer unit tests check that a certain number of bindings are executing within a certain period of time. Running the test with a log-level equal to Emerg will make the assertion pass, while setting it equal to Data will make it fail. A bug which only appears under certain debugging conditions is called a Heisenbug. Be wary of the logging level...