Logging and Tracing in C++ Simplified: Traveling the Road Last Traveled by a Previously Invented Wheel

by Mo Budlong

THIS INFORMATION AND EXAMPLES OF CODE ARE BEING PROVIDED BY SUN AS A COURTESY, "AS IS," AND SUN DISCLAIMS ANY AND ALL WARRANTIES PERTAINING THERETO, INCLUDING ANY WARRANTIES OF MERCHANTABILTY, FITNESS FOR A PARTICULAR PURPOSE, OR NON-INFRINGEMENT.

Summary

Tracing and logging is a common aid to, and sometimes a critical path for, debugging. The Open Source log4cpp package simplifies the process of setting up logging and tracing in C++ applications. The documentation on log4cpp is missing some simple examples on using the log4cpp object suite and this article provides examples and explanations as well as a simple fix to a small bug in log4cpp.

Logging and Tracing

You should trace. Got it? Sure you do, but back up a bit. If you write an application of more than 500 lines, or the application runs as a daemon or service, or you want to save yourself a lot of debugging headaches - you should trace. Which, brings you back around to the original statement. You should trace.

Ah, but, how does a C++ program do its tracing?

If you came up through the ranks of procedural languages, that is C, you are probably used to the old:

<listing>
#ifdef DEBUG
	fprintf(trace_file,"Here is a useless trace 
        message\n");
#endif
</listing>

But object oriented languages are uh . . . object oriented. Spewing random messages to a trace file isn't quite elegant enough, not to mention just plain not objectivied, objectilated, . . . whatever.

You need a tracing and logging class.

No, no, it's not written here for you because it's already taken care of. Ceki Gülcü created a powerful set of logging and tracing objects in Java[tm] named log4j. Bastiaan Bakker ported most of the same set of objects to C++ and calls it log4cpp. They are both open source packages, freely available at sourceforge.net and other open source repositories.

Inserting logging and tracing into code has been around since code was first authored using a hammer and chisel. The technique is low-tech, but it is also very effective. If it is done correctly, it can even form the basis of auditing the software and become an effective error logging tool.

Logging can slow down a program, and the authors of log4j and log4cpp worked very hard to tweak those portions of the code that could cause slowness.

Metrics are hard to quote, because of the wide variance in the volume of trace messages. At one end you can trace only the severe messages

<listing>
#ifdef DEBUG
	trace("Captain, the dilithium crystals are melting\n");
#endif
</listing>

At the other, you can trace almost every line of code.

The important thing for a tracing class is that its mere existence in an application should not unduly slow down the application. The log4cpp package does an excellent job in this regard.

Where log4cpp falls down is the documentation. Each individual class is thoroughly documented, but there is little or nothing on how to tie the objects together to use log4cpp. The log4cpp document states "it is like log4j." If you hunt down documentation on log4j it consists of a one-article introduction to using log4j.

So, if you are interested in logging and tracing and would like to use an excellent and freely available tracing tool, read on.

log4cpp has three main components: categories, appenders, and layouts.

A layout class controls what the output message is going to look like. You may derive your own classes from Layout, to specify any style of output message that you want. log4cpp comes with two layout classes, SimpleLayout and BasicLayout.

An appender class writes the trace message out to some device. The messages have been formatted by a layout object. log4cpp comes with classes to "append" to standard out, a named file, or a string buffer. The Appender class works closely with the Layout class, and once again you may derive your own appender classes if you wish to log to a socket, a shared memory buffer, or some sort of delayed write device. log4cpp comes with three useful appenders: FileAppender, OstreamAppender, and StringQueueAppender.

A category class does the actual logging. The two main parts of a category are its appenders and its priority. Priority controls which messages can be logged by a particular class. When a category object is created, it starts life with a default appender of standard out and a default priority of none. One or more appenders can be added to the list of destinations for logging. There will be more on appenders in a moment. The priority of a category can be set to NOTSET, DEBUG, INFO, NOTICE, WARN, ERROR, CRIT, ALERT or FATAL/EMERG in ascending order of "logginess" or importance level of each message. FATAL and EMERG are two names for the same highest level of importance. Each message is logged to a category object. The category object has a priority level. The message itself also has a priority level as it wends its way to the log. If the priority of the message is greater than, or equal to, the priority of the category, then logging takes place, otherwise the message is ignored. The category priorities are arranged such that:

<listing>
NOTSET < DEBUG < INFO < NOTICE < WARN < ERROR < CRIT 
       < ALERT < FATAL = EMERG
</listing>

FATAL and EMERG are equal and are the highest level. NOTSET is the lowest and if a category object is left with a NOTSET priority, it will accept and log any message.

Messages can be given any of these priorities except NOTSET.

So if a category has been set to level WARN, then messages with levels DEBUG, INFO and NOTICE will not be logged. Messages set to WARN, ERROR, CRIT, ALERT, FATAL or EMERG will be logged.

Categories are arranged in a tree with the root node being the top level category. This allows you to break tracing down into layers (categories). Children categories, when first created, inherit the priority of their parent category. In practice this is not very useful, but you have not yet fully exercised log4cpp.

Appenders accumulate as a collection on a category object. When an appender is added to a category, the default behavior is for the appender to be added to the list of destinations for logging messages. It would be possible to log/trace into two files simultaneously as well as echoing to standard out.

In practice you rarely want to log to more than one place at a time, and the single destination that you do want is almost never standard out. log4cpp allows this to be handled with an additivity flag. If the additivity property is set to false, then when a new appender is attached to a category object, it is not added to the destination list. Instead, it replaces the current list of appenders on that category object.

How does all this hang together?

The Category class creates one overall static root category object (called root). The application can create instances of children categories from this one static parent.

Here is a simple example of using log4cpp.

Unless you want to use the basic logging setup of a simple layout sent to standard out, there are six initial steps to using a log4cpp log:

1. Instantiate an appender object.
2. Instantiate a layout object.
3. Attach the layout object to the appender.
4. Instantiate a category object by calling the static function log4cpp::Category::getInstance("name").
5. Attach the appender object to the category as an additional appender (in addition to the default standard out appender), or set Additivity to false first and install the appender as the one and only appender for that category.
6. Set a priority for the category unless you simply want to log everything.

<listing>
// TestLog4CPP.cpp : A small exerciser for log4cpp

#include	"Category.hh"
#include	"FileAppender.hh"
#include	"BasicLayout.hh"

int main(int argc, char* argv[])
{
        // 1 instantiate an appender object that 
        // will append to a log file
	log4cpp::Appender* app = new 
              log4cpp::FileAppender("FileAppender",
              "/logs/testlog4cpp.log");

        // 2. Instantiate a layout object
	// Two layouts come already available in log4cpp
	// unless you create your own.
	// BasicLayout includes a time stamp
        log4cpp::Layout* layout = 
        new log4cpp::BasicLayout();

	// 3. attach the layout object to the 
	// appender object
	app->setLayout(layout);

	// 4. Instantiate the category object
	// you may extract the root category, but it is
	// usually more practical to directly instance
	// a child category
	log4cpp::Category main_cat = 
        log4cpp::Category::getInstance("main_cat");

	// 5. Step 1 
	// an Appender when added to a category becomes
	// an additional output destination unless 
	// Additivity is set to false when it is false,
	// the appender added to the category replaces
	// all previously existing appenders
        main_cat.setAdditivity(false);

	// 5. Step 2
        // this appender becomes the only one
	main_cat.setAppender(app);

	// 6. Set up the priority for the category
        // and is given INFO priority
	// attempts to log DEBUG messages will fail
	main_cat.setPriority(log4cpp::Priority::INFO);

	// so we log some examples
	main_cat.info("This is some info");
	main_cat.debug("This debug message will 
			         fail to write");
	main_cat.alert("All hands abandon ship");

	// you can log by using a log() method with 
	// a priority
	main_cat.log(log4cpp::Priority::WARN, "This will 
				  be a logged warning");

	// gives you some programmatic control over 
	// priority levels
	log4cpp::Priority::PriorityLevel priority;
	bool this_is_critical = true;
	if(this_is_critical)
		priority = log4cpp::Priority::CRIT;
	else
		priority = log4cpp::Priority::DEBUG;

	// this would not be logged if priority 
	// == DEBUG, because the category priority is 
	// set to INFO
	main_cat.log(priority,"Importance depends on 
					  context");
	
	// You may also log by using stream style
	// operations on 
	main_cat.critStream() << "This will show up 
              << as " << 1 << " critical message" 
	<< log4cpp::CategoryStream::ENDLINE;
        main_cat.emergStream() << "This will show up as " 
		<< 1 << " emergency message" <<       
                log4cpp::CategoryStream::ENDLINE;

	// Stream operations can be used directly 
        // with the main object, but are 
        // preceded by the severity level
	main_cat << log4cpp::Priority::ERROR 
              << "And this will be an error"  
              << log4cpp::CategoryStream::ENDLINE;

	// This illustrates a small bug in version 
	// 2.5 of log4cpp
	main_cat.debug("debug"); // this is correctly 
				 // skipped
	main_cat.info("info");
	main_cat.notice("notice");
	main_cat.warn("warn");
	main_cat.error("error");
	main_cat.crit("crit");	// this prints ALERT 
				// main_cat : crit	
	main_cat.alert("alert");// this prints PANIC 
				// main_cat : alert
	main_cat.emerg("emerg");// this prints UNKOWN 
				// main_cat : emerg


	main_cat.debug("Shutting down");// this will 
					// be skipped

	// clean up and flush all appenders
	log4cpp::Category::shutdown();
	return 0;
}

</listing>

The final section of the code in this example illustrates a bug in log4cpp. In BasicLayout() a message is logged as:

<listing>
date_time PRIORITY category_name : message
</listing>

The following listing is an example of the output from this program. Note that the crit() method prints ALERT as the priority level, the alert() method prints PANIC as the priority level, and emerg() prints UNKNOWN as the priority level.

<listing>
995871335 INFO main_cat : This is some info
995871335 PANIC main_cat : All hands abandon ship
995871335 WARN main_cat : This will be a logged warning
995871335 ALERT main_cat : Importance depends on context
995871335 ALERT main_cat : This will show up as 1 
		           critical message
995871335 UNKOWN main_cat : This will show up as 1 
			    emergency message
995871335 ERROR main_cat : And this will be an error
995871335 INFO main_cat : info
995871335 NOTICE main_cat : notice
995871335 WARN main_cat : warn
995871335 ERROR main_cat : error
995871335 ALERT main_cat : crit
995871335 PANIC main_cat : alert
995871335 UNKOWN main_cat : emerg
</listing>

So perhaps last but not least, you come to the beauty of open source. Found a bug? Just go ahead and fix it.

The following listing is a copy of the Priority.cpp file, part of the full distribution of log4cpp.

The name of a priority is created from a static array and an index created based on the priority number.

<listing>
/*
 * Priority.cpp
 *
 * Copyright 2000, LifeLine Networks BV 
 * (www.lifeline.nl). All rights reserved. 
 * Copyright 2000, Bastiaan Bakker. All rights reserved.
 * See the COPYING file for the terms of usage and 
 * distribution.
 */

#include "Portability.hh"
#include "Priority.hh"

namespace log4cpp 
{

    const std::string& 
    Priority::getPriorityName(int priority) throw() 
    {
        static std::string names[9] =  
        {
          "PANIC", "ALERT", "ERROR", "WARN", 
          "NOTICE", "INFO", "DEBUG", "NOTSET", 
          "UNKOWN" 
        };
        
        priority++;
        priority /= 100;
        return ((priority < 1) || (priority > 8)) ?
            names[8] :
            names[priority - 1];
    }
}
</listing>

But the priority numbers are slightly different than this function expects as shown below in an extract from Priority.hh.

<listing>
typedef enum {EMERG  = 0, 
		      FATAL  = 0,
                      ALERT  = 100,
                      CRIT   = 200,
                      ERROR  = 300, 
                      WARN   = 400,
                      NOTICE = 500,
                      INFO   = 600,
                      DEBUG  = 700,
                      NOTSET = 800
        } PriorityLevel;

</listing>

So the fix is to adjust the array and code as follows (Changes are underlined)

<listing>
/*
 * Priority.cpp
 *
 * Copyright 2000, LifeLine Networks BV (www.lifeline.nl). 
 * All rights reserved.
 * Copyright 2000, Bastiaan Bakker. All rights reserved.
 *
 * See the COPYING file for the terms of usage and 
 * distribution.
 */

#include "Portability.hh"
#include "Priority.hh"

namespace log4cpp 
{

    const std::string& 
    Priority::getPriorityName(int priority) throw() 
    {
        static std::string names[10] =  
           {
	     "PANIC", "ALERT", "CRITICAL", 
	     "ERROR", "WARN", "NOTICE", "INFO", 
	     "DEBUG", "NOTSET", "UNKOWN" 
	   };

        priority++;
        priority /= 100;
        return ((priority < 0) || (priority > 8)) ?
            names[9] :
            names[priority];
    }
}
</listing>

log4cpp is very flexible and friendly. You can modify it to format any way you want and log to multiple output destinations. It will save you many development hours on many projects. Hats off to Mr. Bakker.

It is still missing one critical piece. The Java[tm] version log4j included a Configurator class that took a configuration from an XML or other set up file so that the "logginess" of a program could be changed without having to modify the code. This would be a dynamite addition to log4cpp.

Does this give you any ideas?

Resources

sourceforge.net is an excellent resource for open source software. As well as log4cpp and log4j you will find log4p for Perl, another log4p for Python, and a log4d, an ongoing project for creating similar logging facilities for Delphi.

The introduction to using log4j and other documentation that has applicability to log4cpp is at The Jakarta Project.

About the Author

Mo Budlong is president of King Computer Services and has been creating utilities, applications, and client server solutions on UNIX® boxes for over 15 years. He has published numerous books and articles on subjects ranging from Assembly language to XML. He is the author of the web based UNIX 101 column, and is soon publishing a book on UNIX basics. Mo is also a musician who plays guitar, bass, and keyboards, and messes around with several other instruments. He lives in Southern California with this wife, daughter, and The Cat.

August 2001

Reader Feedback Tell us what you think of this article. Very worth reading Worth reading Not worth reading If you have other comments or ideas for future articles, please type them here:

Back to Top