Next: Modules, Algorithms and Candidates Up: The MINOS Off-line Software Previous: Job Control Contents

Subsections

Message Service

Last significant change: 2005/03/04

Introduction

The message service serves two main functions. The first is to provide a convenient way to output formatted numerical data as the C++ ``'' operator is lacking in this regard. The second is to provide a utility to filter and direct text output such as debugging, warning, and error messages. The MINOS C++ coding conventions state that users are to use the message service rather than cout and cerr directly so that these messages are processed in a uniform way.

Configuring Message Service from Loon

In your loon .C script, you can configure Message service using a JobC object (even if you're not otherwise using JobControl).

Setting Logging Levels

You can set the log levels for different streams by doing:

{
  JobC jc;
  jc.Msg.SetLevel("Ugli","Warning"); // Print out only warning, 
                                     // error, and fatal messages
	                             // from UgliGeometry
}

The hiearchy of message levels is:

Fatal Really bad errors that are probably going to crash the program

Error Reports of something that has gone badly wrong

Warning Report of a problem that indicates a potential problem or suspect results

Info Messages related to normal operation.

Synopsis Summary information about how things are working

Debug Messages used primarly for debugging

Verbose Gory detail

By default, all streams are set to show Info messages and above.

Lowering the log level of any stream below the Info level can slow down the execution of the entire program. This is due to the extra overhead of looking up stream names when individual messages are filtered. In general, Debug and Verbose should be used with care (since they tend to spew quite a bit of spam).

Setting Stream Formats

Messages can be prefixed by information strings by setting the stream format flags.

Format Description Example

Priority Shows the level of the message =W=

Name Name of the stream MyStream

Host Name of the CPU running the job laptop.domain.edu

PID Process ID of the job laptop.domain.edu:26911

Time Time the message was printed 2005/03/04 14:39:38

File Name of file (if not using CVSid) MyClass.cxx

CVSId CVS revision of the file MyClass.cxx,v1.24

Line Line number of the message MyClass.cxx,v1.24:123

RunSnarl Run and Snarl number of the event [10123|5]

StackTrace Generates a stack trace of the code see below

Bold Make the prefix boldface

Dim Make the prefix dim

Underline Make the prefix underlined

Blink Make the prefix flash on the screen (insert migrane here)

Reverse Make the prefix inverse text

Black Make the prefix text black

Green Make the prefix text green

Yellow Make the prefix text yellow

Blue Make the prefix text blue

Magenta Make the prefix text black

Cyan Make the prefix text cyan

White Make the prefix text white

BgWhite Make the prefix text background white

... ...

BgBlack Make the prefix text background black

ColorAll Apply color/typeface to the entire message (Use at your own risk)

Table 2.2 shows the default formats that are applied to each stream.

You can change the defaults by doing the following at the beginning of your job:

{
   JobC jc;
   jc.Msg.SetDefaultFormat("Bold","Warning"); // Makes all warnings (and only warnings) bold
   jc.Msg.SetDefaultFormat("Blink","Error");  // Makes errors flash
   jc.Msg.SetDefaultFormat("RunSnarl");       // Turns on [run|snarl] for all messages
   // N.B. This only works before you make your path!

   jc.Path.Create()...
}

At any time, you can change the format on a specific stream with the Format command:

  jc.Msg.Format("Ugli:Warning","Bold");           // Makes Ugli warnings bold
  jc.Msg.Format("Ugli:Warning","Priority",false); // Turns off =W= on Ugli warnings.

The color and style formats use ANSI/Xterm escape codes. They are useful for looking at the output of the job by eye, but may not work on all terminals. If you redirect standrard output (for instance, because you are running batch jobs) then you can look at the resulting output with the ``less'' command using:

 \$ less -r loondump.txt

The StackTrace option is special in that it generates many lines of output (and takes a long time to build!) but can greatly ease debugging. The StackTrace format creates a short 'call list' of the functions currently being called.

For instance, assume that you are seeing a strange warning from the Plex: ``can not GetBestItem() from an empty list'', and you don't know what is causing it. Turn on the stack trace option with:

  jc.Msg.Format("Plex:Warning","StackTrace");

and then every time Plex generates a warning, you will see something like:

=W= Plex PlexSEIdAltL.cxx,v1.33:357> Stack Trace:
  [0] PlexSEIdAltL::GetBestItem() const @ MessageService/MsgStream.h:96
  [1] Coroner::RecordDeadStrips(Morgue*, CandRecord const*) @ Plex/PlexSEIdAltLItem.h:46
  [2] Coroner::Reco(MomNavigator*) @ Morgue/Coroner.cxx:87
  [3] JobCMethod::Execute(JobCModule*, MomNavigator*) const @ JobControl/JobCMethod.cxx:70
... Message: can not GetBestItem() from an empty list

This works just like gdb doing a 'where' command. It is easy to see that the function Coroner::RecordDeadStrips is causing the problem.

Writing Code using MessageService

Basics

The MessageService also allows users to send text messages to output streams. Each message is associated with a given package (specified by the prefix chosen for the package) and a priority level. The simplest use looks like this:

#include "MessageService/MsgService.h"
.
.
.
// The CVSID line is required so that the message service can tag 
// error messages with the version number attached to this file.
// The quoted string must start and end with a dollar sign and
// the starting dollar sign should be followed by 'Id:'; CVS will 
// expand the field between the colon and the trailing dollar sign 
// upon any commits, so nothing special need be there initially.
// Code that uses DbiResultPtr from the DatabaseInterface package
// must have CVSID after the MsgService.h include, but before the
// #include "DatabaseInterface/DbiResultPtr.tpl".
CVSID("$Id: message_service.tex,v 1.9 2007/03/01 16:27:38 rhatcher Exp $");
.
.
.
{
  MSG("Pkg", Msg::kVerbose)  << "This is a VERBOSE message\n";
  MSG("Pkg", Msg::kDebug)    << "This is a DEBUG message\n";
  MSG("Pkg", Msg::kSynopsis) << "This is a SYNOPSIS message\n";
  MSG("Pkg", Msg::kInfo)     << "This is an INFO message\n";
  MSG("Pkg", Msg::kWarning)  << "This is a WARNING message\n";
  MSG("Pkg", Msg::kError)    << "This is an ERROR message\n";
  MSG("Pkg", Msg::kFatal)    << "This is a FATAL message\n";

  MsgStream& m = MSGSTREAM("Pkg", Msg::kInfo);
  m << "This construct bypasses test to see if stream is active\n";
}

which sends text messages from package Pkg with various priorities ranging from lowest to highest. The threshold for printing can be set package by package. For example, if you wanted to see all the Debug messages but not all the Verbose messages from the package Pkg you would set the threshold for the package Pkg to Debug. The default threshold is Info.

Note that messages that are below print threshold are not formatted. This means that unprinted messages cause only a negligible performance hit. On my machine (Pentium 350 MHz) the performance hit from 100000 unprinted messages was a total 0.15 seconds.

Very frequently, you will want a message that only prints the first few times the function is called. Although this is simple code to write, it can get very tedious and wordy. Thus was born the MAXMSG macro:

MAXMSG("Pkg",Msg::kWarning,10) << "This warning will print only 10 times." << endl;

MAXMSG works by inserting a few lines of code (including a static variable to track message counts) into your code by use of a C macro, but otherwise works similarly to MSG.

Formatting Numerical Data

The message service provides a simple class to allow users to specify the width and precision of numerical output in much the same way as provided by the C routine printf. For example:

#include "MessageService/MsgService.h"
#include "MessageService/MsgFormat.h"

int main(void) 
{
  int    i = 12345;
  double x = 123.456; 	
  MsgFormat ifmt("%9d");
  MsgFormat ffmt("%9.3f");

  // Don't worry about the MSG thing - its covered in the 
  // next section. Just think of it as a tricky "cout"
  MSG("XXX",Msg::kInfo) << "[" ifmt(i) << "]" << endl;
  MSG("XXX",Msg::kInfo) << "[" ffmt(x) << "]" << endl;
}

will print the number 12345 using a width of 9 characters and 123.456 with a width of 9 characters with a precision of 3 places beyond the decimal point. Output looks like this:

[____12345]
[__123.456]

where the underscores mark blank spaces. The formating options available are summarized in table 2.1.

-	Left justify in field
+	Always show sign
O	Pad left with zeros
o	Octal format
x,X	Hexadecimal format
f	Fixed format
e,E	Scientific format
g,G	General format

Hints and Tips

Easy formating.

Do you miss the old printf() format? No problem.. ROOT has a convenient way to do this using the Form() function.

#include "TString.h"
...
MSG("Pkg",Msg::kInfo) << Form("Number: \%3d 0x\%x \%10.2f",a,b,c) << std::endl;

Form() uses as set of circular buffers, so you can nest them safely. This is often the most convient way to do a lot of formatting.

Don't forget Munits!

Remember that all internal values used by our framework should be expressed as Munits. Whenever you print out a value, you should do the conversion explictly. For example:

#include "TString.h"
...
MSG("Pkg",Msg::kInfo) << "Time between digits: " << delta_t/Munits::ns<< endl;
MSG("Pkg",Msg::kInfo) << "Energy of the proton:" << e_prot/Munits::MeV << endl;

Remember the rule: divide when printing.

Use MAXMSG

If your screen is full of messages, it's hard to pull out the important ones. If you have a message that is likely to keep complaining through a job, but is also likely to be unimportant, then use the MAXMSG macro. For instance, it is used a lot in the Calibrator, where you may want to alert the user that a calibration isn't available, but you don't want to print an error line ever time a channel is calibrated through the whole job.

Setting the default format.

At the very beginning of your .C script, you can set all the MessageService formats to new defaults. This must be done before the Path has been created, so this should go at the top of you script. This is Nathaniel's current favorite setup:

  JobC jc;
  jc.Msg.SetDefaultFormat("RunSnarl,Bold","Warning");
  jc.Msg.SetDefaultFormat("RunSnarl,Reverse,Red","Error");
  jc.Msg.SetDefaultFormat("RunSnarl,StackTrace,Reverse,Red","Fatal");	
  jc.Path.Create(...)

Changing levels.

You can change the log level of a stream from within you code using:

MsgService::Instance()->GetStream("Pkg")->SetLogLevel(Msg::kDebug);

Advanced Features

Table 2.2: Default information attached to each message.

	Priority	Prefix	Date	File	CVS Version	Line #
Verbose	x	x
Debug	x	x
Synopsis
Info
Warning	x	x
Error	x	x	x	x	x	x
Fatal	x	x	x	x	x	x

The following outlines some of the more advanced features of the MessageService. Note that many of the code fragments shown will eventually be replaced by commands available from the JobControl package.

Writing message service streamers for your classes The message service can write output for any class that has an operator ostream& operator« defined. So, to write a class ``C'' out:
```
#include <iostream>
class C
{
  friend class ostream& operator<<(ostream& os, const C& c) {
    return os << c.fData1 << "," << c.fData2;
  }
};
```
Any class that can be writen via ``cout « c'' to also use ``MSG(...) « c;'' without any modification.
Sending Messages to Multiple Output Streams The message service allows messages to be send to multiple output streams. For example, if you wanted messages from package Pkg to go to both cout and a file PkgInfo.txt you would use:
```
MsgService::Instance()->
  GetStream("Pkg")->AttachOStream(Msg::kInfo,"PkgInfo.txt");
```

Merging of Two Output Streams The output of two streams can be merged like this:

MsgService::Instance()->
  GetStream("PkgA")->AttachOStream(Msg::kInfo,"merge.txt");
MsgService::Instance()->
  GetStream("PkgB")->AttachOStream(Msg::kInfo,"merge.txt");

In this case Info messages from both PkgA and PkgB will be merged in the file merge.txt.

Concatenation of Two Output Streams The output of two streams can be concatenated automatically like this:
```
MsgService::Instance()->
  AddCatStream("cat.txt","PkgA",Msg::kInfo);
MsgService::Instance()->
  AddCatStream("cat.txt","PkgB",Msg::kInfo);
```
In this case Info messages sent from package PkgA and PkgB will be concatenated together in the file cat.txt.

Changing Format By default, the message service will attach additional information to each message printed. The defaults are listed in table 2.2. To modify the defaults follow these examples:

MsgService::Instance->
  GetStream("PkgA")->AddFormat(Msg::kInfo,Msg::kName);
MsgService::Instance->
  GetStream("PkgA")->RemoveFormat(Msg::kInfo,Msg::kName);
MsgService::Instance->
  GetStream("PkgA")->SetFormat(Msg::kInfo,Msg::kName+Msg::kFile);

Statistics To view the number of messages printed by package and file use:
```
MsgService::Instance()->PrintStatistics();
```

The Trip Wire Debug Facility

In the past we have encountered situations in which the same job, run twice without any intervening change to the software or the data, has produced different results indicating some randomising effect, such as the use of uninitialised data. One way to locate such problems is to use Valgrind. Another is simply to switch all print stream levels to some low level such as Debug, run the job multiple times and find the place where the output files first show differences. The snags of such an approach are:-

Making sure that all print levels are modified - no where is there a list of them all and new ones can be added at any time.
Keeping the log files to a manageable size. If the jobs don't diverge until many events have been processed the approach may be unworkable.
Identifying where the jobs diverge. The MessageService message identifies the function that generates the message but nothing else, i.e. the event or JobCModule module it comes from.

These snags are addressed by a trip wire facility. The basic idea is that the program execution is divided into segments, with a new one starting each time a message is requested. You configure the trip wire to suppress all messages until a particular segment is reach after which all stream message levels are lowered and segment identification is appended to all messages output.

Segments are identified by 3 counters:-

record set

The record set counter starts at zero and is incremented each time a JobCInputModule is called. If simply reading from a DaqSnarl stream then record sets are equivalent to snarls. If reading from multiple streams, a new record set is loaded each time any stream VldContext is crossed - see section 13.4.

node

The node counter starts at zero and is reset to zero each time the record set counter increments. It is incremented each time a node i.e. a JobCModule is called.

call

The call counter starts at zero and is reset to zero each time the node counter increments.

When messages are output, the values of these 3 counters is perpended, for example:-

10:7:47048: DmxUtilities.cxx:1663>  x = 0.238200 y = 0.802147 weight = 0.005958

is call 47048 from node 7 of record set 10. For simple job paths, the node number just corresponds entry in the path, for example in path:-

  jc.Path.Create("Reco",
		 "NoiseFilterModule::Ana "		 
		 "RecordSetupModule::Get "
		 "DigitListModule::Get "
		 "DigitListModule::Reco "
		 "FilterDigitListModule::Reco "
		 "FilterLIModule::Ana "
		 "DeMuxDigitListModule::Reco "
		 "DeMuxCosmicsModule::Ana "
		 "StripSRListModule::Reco "
		 "SliceSRListModule::Reco "
		 "ClusterSRListModule::Reco "
		 "ShowerSRListModule::Reco "
		 "TrackSRListModule::Reco "
		 "FitTrackSRListModule::Reco "
		 "EventSRListModule::Reco "
		 "RecordSetupModule::Reco "
		 "Output::Put");

node 7 would be:-

DeMuxDigitListModule::Reco

The trip wire facility is activated through the environmental variable: ENV_MSG_TRIP_WIRE which defined as a string containing 4 space-separated integers, the first three giving the record set, node and call values and the last the log level to be used once the trip wire point is reached. For example:-

    setenv ENV_MSG_TRIP_WIRE "4 3 2 1"

would set the trip wire to record set 4, node 3 call 2 and set the log level to 1 (debug). A typical way to look for problems would be to have a long run with only moderate (info) printout from the start:-

    setenv ENV_MSG_TRIP_WIRE "0 0 0 3"

then if a divergence is found on say record set 1234, have a second run that just processed 1234 record sets with:-

    setenv ENV_MSG_TRIP_WIRE "1234 0 0 0"

so that the record set has debug set to maximum.

A single MswTripWire object is used to hold the trip wire setting, the current program segment and the current log level. As an additional debug facility it has the dummy member function

  void Activated() const;

which is called just once, as the trip wire point is passed. Having found a divergence point the trip can be set to an earlier segment, the program debugged and a break point set on

  MswTripWire::Activated()

to starting looking for the problem with the debugger.

Next: Modules, Algorithms and Candidates Up: The MINOS Off-line Software Previous: Job Control Contents

Robert Hatcher 2009-11-16

Fatal	Really bad errors that are probably going to crash the program
Error	Reports of something that has gone badly wrong
Warning	Report of a problem that indicates a potential problem or suspect results
Info	Messages related to normal operation.
Synopsis	Summary information about how things are working
Debug	Messages used primarly for debugging
Verbose	Gory detail

Format	Description	Example
Priority	Shows the level of the message	=W=
Name	Name of the stream	MyStream
Host	Name of the CPU running the job	laptop.domain.edu
PID	Process ID of the job	laptop.domain.edu:26911
Time	Time the message was printed	2005/03/04 14:39:38
File	Name of file (if not using CVSid)	MyClass.cxx
CVSId	CVS revision of the file	MyClass.cxx,v1.24
Line	Line number of the message	MyClass.cxx,v1.24:123
RunSnarl	Run and Snarl number of the event	[10123\|5]
StackTrace	Generates a stack trace of the code	see below
Bold	Make the prefix boldface
Dim	Make the prefix dim
Underline	Make the prefix underlined
Blink	Make the prefix flash on the screen	(insert migrane here)
Reverse	Make the prefix inverse text
Black	Make the prefix text black
Green	Make the prefix text green
Yellow	Make the prefix text yellow
Blue	Make the prefix text blue
Magenta	Make the prefix text black
Cyan	Make the prefix text cyan
White	Make the prefix text white
BgWhite	Make the prefix text background white
...	...
BgBlack	Make the prefix text background black
ColorAll	Apply color/typeface to the entire message	(Use at your own risk)