Logging and Tracing for Fun and Profit: C++ Edition

Most of us are accustomed to using std::cout for debugging and tracing, especially when developing small applications. Quickly though, using naive I/O for debugging becomes really tedious.

The usual progression for me is just printing to standard out, then redirecting to a file, then using grep to pull specific information out of the file, to needing to use concurrency or something like that, and then everything goes down the toilet.

You may also like: Zipkin vs. Jaeger: Getting Started With Tracing

You have nonsensical logging output that's unusable. You can't really trace execution anymore because you don't have accurate timestamps. You have a hard time finding the information you need. Things are just a mess.

This is when you decide to move to a dedicated logging platform.

There are a few strong logging systems out there for C++. Today, we're going to talk about one of the more popular ones, Apache's log4cpp.

Log4cpp is widely used and is integrated into a fair number of applications already. Let's take a look at how we can use it. In our example, we're going to create two classes, a printer and a fancy_printer (I know, too intense!). The printer prints it's own message, while the fancy printer prints yours.

The initial class definitions are:

class printer {

private:

    const std::string message;

public:

    printer();

    void print() const;

};

and

xxxxxxxxxx

class fancy_printer {

public:

    void print(const std::string message) const;

};

Nice and simple, to the point. Let's just get some printing done, right? Now let's add some log4cpp code:

xxxxxxxxxx

class printer {

private:

    log4cpp::Category& log;

    const std::string message;

public:

    printer();

    void print() const;

};

and

xxxxxxxxxx

class fancy_printer {

private:

    log4cpp::Category& log;

public:

    fancy_printer();

    void print(const std::string message) const;

};

This has forced a couple of changes on us. First, we're defining the log in the class interface. Second, we've had to add a constructor to the fancy_printer. Why? Well, we need to configure the log. The constructor looks something like this:

xxxxxxxxxx

fancy_printer::fancy_printer() :

    log(log4cpp::Category::getInstance(std::string("fancy_printer"))) {

    log4cpp::Appender *appender = new log4cpp::OstreamAppender("console", &std::cout);

    appender->setLayout(new log4cpp::BasicLayout());

    log.addAppender(appender);

}

This isn't bad, but it's in the constructor, and it essentially the same in both the printer and fancy_printer classes. The code is eminently reusable. It's not really coupled to the primary purpose of the printer and fancy_printer types either. Overall, kind of a naive approach. So how can we do better?

Use a factory function.

xxxxxxxxxx

namespace logging {

    log4cpp::Category& get_log(const std::string name) {

        log4cpp::Category& log = log4cpp::Category::getInstance(std::string(name));

        log4cpp::Appender *appender = new log4cpp::OstreamAppender("console", &std::cout);

        appender->setLayout(new log4cpp::BasicLayout());

        log.addAppender(appender);

        return log;

    }

}

Then, your constructors look something like this:

xxxxxxxxxx

fancy_printer::fancy_printer() :

    log(logging::get_log("fancy_printer")) {}

Now you have introduced a dependency on the get_log(), but that's manageable, and you've been able to remove a bunch of redundant code from your classes that isn't related to class responsibilities. Win-win!

Finally, we want to add support for properties files. Remember, log4cpp is derived from log4j, and uses a similar properties file format for logger configuration. As your program grows, this becomes more and more useful. So let's put one together, and read it into the logging system at startup.

We're going to use a simple properties file that copies our previous functionality and configures the loggers at different levels:

xxxxxxxxxx

log4cpp.rootCategory=WARN, rootAppender

log4cpp.category.printer=DEBUG

log4cpp.appender.rootAppender=ConsoleAppender

log4cpp.appender.rootAppender.layout=BasicLayout

Here, we've configured the logging system as a whole to log at the WARN level, while the printer logger is configured to log at DEBUG. Also note that categories are classified by the name you give them in your code, so log4cpp.category.printer refers to the printer logger, while the log4cpp.category.rootCategory sets properties for the entire logging system.

We are using a ConsoleAppender with a BasicLayout, which is how we had configured the system previously. You can also set different appenders and configurations on a per-log basis, so you could create a different appender for the printer or the fancy_printer loggers that, say, log to files, or use a different layout.

Now, our factory function looks like this:

xxxxxxxxxx

namespace logging {

    log4cpp::Category& get_log(const std::string name) {

        std::string initFileName = "{WORK_DIR}/log4cpp.properties";

        log4cpp::PropertyConfigurator::configure(initFileName);

        return log4cpp::Category::getInstance(std::string(name));

    }

}

There you go! You now have an external file you can configure your loggers with and nicely separated logic for log management. Hope this helps you as much as it has helped me.

Further Reading

Distributed Tracing With Zipkin and ELK

Knative Monitoring, Logging, and Tracing Explained

Monitoring Microservices With Spring Cloud Sleuth, Elastic Stack, and Zipkin