Logging is a critical technique for troubleshooting and maintaining software systems. It's simple, provides information without requiring knowledge of programming language, and does not require specialized tools. Logging is a useful means to figure out if an application is actually doing what it is supposed to do. Good logging mechanisms can save long debugging sessions and dramatically increase the maintainability of applications.
In this article, I present a simple—but highly useful—logging framework that is typesafe, threadsafe (at line-level), efficient, portable, fine-grained, compact, and flexible. The complete source code, which works with Visual C++ 7.1, g++ 3.3.5, and CC 5.3 on Sun and other platforms, is available in the DDJ October 2007 zip file at www.ddj.com/code/.
In Part 2 of this article, I enhance this technique by providing more granularity.
The First Step
Let's take a first stab at a Log class. Listing One uses an std::ostringstream member variable called "os" to accumulate logged data. The Get() member function gives access to that variable. After all data is formatted, Log's destructor persists the output to the standard error. You use Log class like this:
Log().Get(logINFO) << "Hello " << username;
Executing this code creates a Log object with the logINFOx logging level, fetches its std::stringstream object, formats and accumulates the user-supplied data, and finally, persists the resulting string into the log file using exactly one call to fprintf().
Why flush during destruction? The last two steps are important because they confer threadsafety to the logging mechanism. The fprintf() function is threadsafe, so even if this log is used from different threads, the output lines won't be scrambled. According to gnu.org/software/libc/manual/html_node/Streams-and-Threads.html:
Listing One
// Log, version 0.1: a simple logging class
enum TLogLevel {logERROR, logWARNING, logINFO, logDEBUG, logDEBUG1,
logDEBUG2, logDEBUG3, logDEBUG4};
class Log
{
public:
Log();
virtual ~Log();
std::ostringstream& Get(TLogLevel level = logINFO);
public:
static TLogLevel& ReportingLevel();
protected:
std::ostringstream os;
private:
Log(const Log&);
Log& operator =(const Log&);
private:
TLogLevel messageLevel;
};
std::ostringstream& Log::Get(TLogLevel level)
{
os << "- " << NowTime();
os << " " << ToString(level) << ": ";
os << std::string(level > logDEBUG ? 0 : level - logDEBUG, '\t');
messageLevel = level;
return os;
}
Log::~Log()
{
if (messageLevel >= Log::ReportingLevel())
{
os << std::endl;
fprintf(stderr, "%s", os.str().c_str());
fflush(stderr);
}
}
The POSIX Standard requires that by default the stream operations are atomic...issuing two stream operations for the same stream in two threads at the same time will cause the operations to be executed as if they were issued sequentially. The buffer operations performed while reading or writing are protected from other uses of the same stream. To do this, each stream has an internal lock object that has to be (implicitly) acquired before any work can be done.
Before moving on to a more efficient implementation, let's write code to insert tabs in proportion to the logging level, and append an std::endl to each chunk of text. This makes the log line oriented and easy to read by both humans and machines. Here's the relevant code:
Log::ReportingLevel() = logDEBUG2;
const int count = 3;
Log().Get(logDEBUG) << "A loop with " << count << " iterations";
for (int i = 0; i != count; ++i)
{
Log().Get(logDEBUG1) << "the counter i = " << i;
}
which outputs:
- 22:25:23.643 DEBUG: A loop with 3 iterations - 22:25:23.644 DEBUG1: the counter i = 0 - 22:25:23.645 DEBUG1: the counter i = 1 - 22:25:23.645 DEBUG1: the counter i = 2
Indentation makes the logging more readable. More leading tabs imply a more detailed level of logging.
