Monday, April 16, 2007

Logging Adventures in C++, Part 1

One of the most dreadful, and unfortunately most common defects in C / C++ programs, are illegal memory accesses. Debugging such defects is difficult enough because of their delayed nature (an application can still run for awhile after the illegal access); but even when an application does crash right after the error, the developer is left with no information at all, not even a stack trace to point out the offending code fragment. C++ programmers are additionaly frustrated by the fact that, while the language's exception mechanism could be used to address this problem, memory errors are reported through C's signal API, which bypasses try..catch blocks. Visual debuggers can be of help here, but sometimes they are of little help – either because the defect only shows itself in the production environment, or because it happens somewhere in a long, difficult to trace chain of method invokations.

When faced with such situatiosn, developers will often start filling their code with printf() calls, tracking execution with increasingly finer resolution until the exact line generating the error is found. While effective, this technique is rather cumbersome, in that we often get a long, time-conssuming dump whose only interesting part is the last line. It would be better to have some way to silently keep track of the program's state until it crashes, only then receiving a message that hints on the defect's source – it wouldn't hurt to have some way to automatically rip it off, too, in case of production-time performance concerns.

The code snippet below illustrates how such a tracking mechanism can be implemented on signal handlers, a (wisely) rarely used feature of the C language. In short, it provides a trace() function, which you call periodically (say, at the beggining of each method call?) to keep track of your application's state, and a signal handler that will print out the last trace()'d state uppon crashing. Everytime you face a crashing problem, start filling the code wih trace() calls until the offending fragment shows up; as your application gets increasingly trace()'d, it gets easier and easier to figure the source of memory errors – a definite improvement over the conventional printf() approach, where the function calls are removed after the immediate defect is found. And, while I personally like the idea of keeping this on at all times, it is easy to compile it off if you have performance constraints.


/* tracer.hpp */

#include <string>
using std::string;

class Tracer
{
private: Tracer();

public: static Tracer& getInstance();

public: void trace(string name);
};

/*
Call this at the beggining of every function, passing it
the function's name and (at your discretion) arguments. If
the application hangs after that, the same string is
printed to the standard error output, giving you an idea
of how far the application went before going kaput.
*/
inline void trace(string name)
{
/* This addresses performance concerns in production
builds. Any reasonably smart compiler will rip off all
invokations of an empty inline function. */
#ifndef NO_TRACING
Tracer& tracer = Tracer::getInstance();
tracer.trace(name);
#endif
};

/* tracer.cpp */

#include "tracer.hpp"

#include <iostream>

#include <csignal>
#include <cstdlib>

using std::cerr;
using std::endl;

static string traced;

void handleSignal(int signal)
{
/* Change the signal handler back to the default,
avoiding recursion in case this function raises the
signal again. */
std::signal(SIGSEGV, SIG_DFL);

/* Print the last trace()'d program state. */
cerr << "Segmentation fault on "
cerr << traced << "." << endl;

/* Terminates the application, as there's nothing more
we can do. */
abort();
}

Tracer::Tracer()
{
trace("Tracer()");

/* Register our custom signal handler. */
std::signal(SIGSEGV, handleSignal);
}

Tracer& Tracer::getInstance()
{
static Tracer* singleton = new Tracer();

return *singleton;
}

void Tracer::trace(string name)
{
traced = name;
}

/* hello_tracer.cpp */

int main(int argc, char *argv[])
{
trace("main()");

int* doomed = NULL;
int randomic = doomed[0];

return 0;
}