Writing a Trace System

Unix is traditionally very text-oriented: configuration files are plain ASCII, commands are issued via the shell, tools provide feedback via stdout, and daemons and other system services record status in logs.

Sometimes syslog or some other third-party package fits the bill. Other times it won’t, in which case you can follow this article’s lead and create your own centralized logging system from scratch. The sample code is in C and C++, but the features and concepts readily translate to other languages.

What is Logging?

The notion of a logging or trace system varies by application, but is essentially a means to mark activity. An application may report directly to the console, record to a central file, or pass messages across a socket or pipe to a dedicated logging service, such as syslog.

The format of a log also varies. Human-readable, ASCII text logs are the most common, but you sometimes run into XML-based or even binary logs (a la lastlog). In the latter two cases, a tool processes the log data into a human-readable format.

The most basic trace system, and one pretty much every developer has seen, is a series of well-placed output statements: simply surround a problem area with printf() calls, rerun the program, and use the messages to narrow the bug hunt. (You can compare this to running a formal debugger in the sidebar “Logging vs. Debugging.”)

printf() is primitive, but effective. However, it becomes troublesome when it grows: the (potentially many) raw printf() or cout calls strewn about the code complicate the very debugging they’re intended to simplify. And, embarrassingly, remnants of the debugging process can even wind up on an end-user’s screen.

Some developers corral those developer-only trace statements with preprocessor #ifdefs (or worse yet, preprocessor pseudo-functions) so they magically disappear from production builds. At first that sounds like a great solution — until those useful trace messages aren’t available when you need them most; when bugs manifest themselves in your branded and shipped “stable” release. Once again, a quick-fix has caused more trouble than it’s worth.

A Centralized Trace System

Another solution to “Stray cout Syndrome” is to replace those calls with a centralized logging system. In “fire-and-forget” fashion, messages are passed to some object or function and it decides what to do with them. For example, if you call your logging system’s equivalent of…

_log->debug(“after call to doSomething()”)

… and if debug output is enabled, your application will report after call to doSomething() to the screen or logfile.

However, if debug output is disabled, you see nothing. And that’s the point. Unlike raw printf(), the messages passed to this sort of logging system only appear when requested.

Turning log output on and off is one desirable feature of a trace system. There are others:

* SIMPLE AND ROBUST. The trace system’s interface should be simple and robust, providing a drop-in replacement for bare printf() and cout. Of course, the trace system should be available globally, too. (Depending on your preferences and programming language, you may achieve app-wide access to the trace system through a global variable or a singleton.)

* MESSAGE CLASSIFICATION. All messages are not equal. Some indicate serious problems, while others provide status information. A trace system should classify and rate messages according to severity, such as debug, info, warning, and error.

* TUNABLE OUTPUT. The system should provide a “knob” to filter messages based on severity.

Depending on the application, other features may be useful or even required. Additional capabilities include:

* CUSTOMIZATION. For apps that log to a file, end-users must be able to choose where the log is written.

* TIMESTAMPS (or other per-entry decorations). Client/server and time-sensitive applications must often track the when as well as the what of each activity.

* RUN-TIME DATA. Recording the calling object’s state or the calling function’s name and parameters can be invaluable in tracking down intermittent problems.

* THREAD-SAFETY. Some client/server tools spawn multiple processes or threads to service a volume of requests, yet log data to a single file. Trace systems are usually thread-safe, preventing garbled output caused by threads competing to write to the log all at once.

* EFFICIENT. Logging systems pass around a lot of character data, which raises eyebrows in the efficiency camp. While it’s good form to follow a language’s basic practices — for example, passing C++ objects by reference or pointer rather than by value — chances are you won’t take a noticeable hit unless you’re writing real-time software.

Once you’ve identified your requirements, designing and building a trace system is relatively straightforward. One example, Logger, implemented in C and C++ and shown in Listing One , is suitable for a single-threaded command line tool.

C:

typedef {

  /*

  Here, full signatures are included for clarity

  In the real C code these are listed as

  function pointers.

  */

  debug( const char* , … ) ;

  debugWithID( const char* , const char* , … ) ;

  info( const char* , … ) ;

  infoWithID( const char* , const char* , … ) ;

  warn( const char* , … ) ;

  warnWithID( const char* , const char* , … ) ;

  error( const char* , … ) ;

  errorWithID( const char* , const char* , … ) ;

  setLevel( int ) ;

  levelUp() ;

  levelDown() ;

} Logger ;
C++:

class Logger {

  public:

  static Logger& getInstance() throw() ;
  void debug( const char* message ) const throw() ;

  void debug( const char* id , const char*

    message ) const throw() ;
  void info( const char* message ) const throw() ;

  void info( const char* id , const char*

    message ) const throw() ;
  void warn( const char* message ) const throw() ;

  void warn( const char* id , const char*

    message ) const throw() ;
  void error( const char* message ) const throw() ;

  void error( const char* id , const char*

    message ) const throw() ;
  void levelUp() throw() ;

  void levelDown() throw() ; 
  void setLevel( MessageLevel newLevel ) throw() ;

} ;

Pay attention to discern between Logger‘s set of public functions, or its interface, and its internals, or implementation. (See Listing One, “Logger Object Interface,” for details.) The implementation is what you would change to enhance performance or to replace the wrapped printf() and cout calls with, say, syslog() or a third-party product.

The center of this show is the Logger object, through which all messages are sent. In lieu of using a global variable, the Logger is globally accessible as a singleton. Client code fetches a reference to the singleton instance via the static class C++ function Logger::getInstance() and from the C function Logger_getInstance().

To distinguish between a message’s severity level, Logger accepts messages via the aptly named member functions debug(), info(), warn(), and error(). Behind the scenes these functions pass their data to printMessage(), which prepends a symbolic level identifier to each log message before printing it. The levels serve as visual cues to make sifting through log messages easier. For example, [!] denotes an error and [W] flags a warning.

Logger compares an internal level setting to that of the incoming message to decide whether to print it. By default, the internal level is info, which means that informational, warning, and error messages are printed, but debug messages aren’t.

The internal level may be adjusted incrementally using Logger‘s levelUp() and levelDown() member functions, or set explicitly using setLevel(). The first two are analagous to the volume knob on a stereo: turning the level up means you want the music louder — all messages, including debug output — while sliding the level down means you want a quiet experience, limiting output to only the most severe messages. These three functions could be used by, say, getopt() to set the level of log detail based on command line switches.

Logger simply wraps calls to printf() and cout. Errors are a special case. Because Logger is for a fictitious command line tool that logs directly to the console, it follows traditional Unix form and sends errors to stderr instead of stdout.

To round out the list of basic amenities, calls to Logger are one-line functions that call printf() or cout under the hood. That’s about as unobtrusive and stable as you can get.

The sample code implements only one of the optional features: run-time information. The name of the current function is passed to Logger and is included in the message output. C and C++ differ slightly in how to achieve this.

C++ supports function overloading, which means that two functions in the same scope can have the same name as long as they take different parameters. The C++ Logger member functions are overloaded to accept the calling function’s name. Compare the following two calls:

_log.debug(“some statement”) ;

_log.debug(“doSomething()” ,

  “some statement, with an ID”) ;

The former prints [D] some statement, while the latter prints [D] doSomething(): some statement, with an ID.

C, on the other hand, does not support overloading. To compensate, Logger provides two member functions per log level. Those named with the WithInfo suffix accept caller info as a separate parameter. The C equivalent to the C++ calls listed above would be:

_log->debug(“some statement”) ;

_log->debugWithId(“doSomething()” ,

  “some statement, with an ID”) ;

The other optional features were thread-safety, per-line decorations (such as timestamps), and the ability to specify a logfile. As this is logging system is designed for a single-threaded, single-process, command line tool that is not time-sensitive, those don’t apply and aren’t implemented.

Logging Data

Adding logging to your application is the easy part: wherever you would have used bare cout or printf() statements, call the appropriate Logger member function instead. The C version uses printf() semantics:

_log->warn(“call to getSomething returns

  %s (%p)”, something, something) ;

Like other printf()-style functions, Logger‘s log functions support a variable number of arguments. This is why their signatures include the ellipsis (…).

The C++ functions take const char* data. You can use stringstream objects to format your message before passing it to Logger:

#include<sstream>

…

std::ostringstream msgStream ;

msgStream << “call from getSomething()

  returns \”"

  << something << std::flush ;

_log->debug(“doHello()” ,

  msgStream.str().c_str()) ;

(For a C++ logging system that’s based on native C++ I/O streams, see the book Applied C++ by Romanik and Muntz.)

The question then becomes what to log and at what level. The answer depends on the application, but here are some helpful guidelines:

* Use the overloaded form of debug(), which takes the calling function’s name as an additional parameter. Often it helps to know where something has gone wrong in addition to what’s gone wrong.

* Flag messages intended for your own consumption as debug messages and leave the remaining message levels for end-users.

* Provide meaningful output. A trace with all messages enabled should give you an outline of program flow, up to and including any mishaps.

* Use printable objects for languages that support them. Printable objects are invaluable in detecting problems when the text representation of an object reveals some internal state. (See the sidebar “Printable Objects To Enhance Meaningful Output” for details.) The sample C++ code includes a Widget class as an example.

But Why Reinvent the Wheel?

One downside to creating your own logging subsystem is that it’s a development effort in and of itself. Depending on your implementation language there may be a number of third-party logging packages available, and it’s worth your time to research them before writing your own. That said, if you write command line tools and/or distribute your code (for free or profit), you may still benefit from writing your own trace subsystem. Dealing with bugs or following upgrades in third-party code can be a hassle Also, every prerequisite that isn’t part of a base OS install is extra baggage for your end-users.

Try the Code

While free of bells and whistles, the sample code (available online) can serve as a base on which to build your own trace system. For example, it wouldn’t be tough to support logging to a file.

Adding logging to an app is best done at design-time. It can be painful to change your trace system, either to replace those old printf()’s or to migrate to a new system.

While creating a logging subsystem can be quite a task, it’s worth the time and effort to centralize and simplify logging to make development, debugging, and deployment easier.