Channels ▼
RSS

C/C++

A Lightweight Logger for C++


In this article, I want to discuss the importance of providing a logging component in your software project. From a very general point of view, any software can be developed in a way that allows the running code to provide a trace of its execution in a log file, then depending on the life phase of the product (development or production), it may be released with a different level of logging set. Having a logger becomes crucial when debugging is not possible or is inconvenient. Under some circumstances, debugging is not possible — for example, because the application runs on specific hardware or the problem is completely unclear. In those cases, collection and analysis of logs is crucial to pinpointing a problem.

At Nokia Siemens Networks, I developed the firmware running on NSN's Base Transceiver Station (BTS). A BTS is very complex hardware driven by impressive firmware. When something does not work (especially in a real network), there is no way to check where the problem traces back other than reading the BTS logs, a common logging platform every subsystem shares with all the other components, which provides prints on different severity levels.

A logger should be effective, efficient, and able to provide clear data. Most importantly, it has to guarantee proper functioning even when the whole system crashes. It makes no sense to write logs if the logger stops running at every crash. The logging platform, like the captain of a sinking ship, must "survive" until the end.

In this article, I develop a small logger that provides two levels of logging and three types of log severity (Error, Warning, and Debug). The code has been used in different projects of different sizes, is thread-safe, computationally lightweight, and easily customizable to work with different log output (to allowing remote logging for example).

Dr. Dobb's has previously published another implementation of a good C/C++ logger (see Logging In C++ and Logging In C++: Part 2). There are few important differences between what you'll see here and that solution. First and most important, the logger discussed here will flush the log messages immediately and will not buffer them, which is crucial when a serious destabilizing event occurs. (The implementation provided in Logging In C++: Part 2 provides the ability to enable or disable a single log print at runtime. The way this feature is implemented is very clever and I encourage you all to take a look at both articles.) Another difference in my implementation is that I use only C++ and STL functionalities (no Boost libraries). To understand the code presented, I expect that you'll be familiar with the variadic template concept of the new C++ standard.

First Look

What a logger should print depends on the kind of application it's written for. In my projects, I've used it to provide at least: the sequential numbering for the logged lines, date, and execution time elapsed since the beginning of the logging period (expressed in ms, it is also very useful to check the execution time for single operations), and some information about the severity of the logged item.

Making a call to the log function should be easy. The logger should be as little invasive as possible, both for the programmer than for the code. If you take a look at Listing One, you'll see how to invoke the logger function just by using the proper c-style macro:

Listing One: logger.hpp.

#ifndef LOGGER_HPP
#define LOGGER_HPP

#include "log.hpp"

static logging::logger< logging::file_log_policy > log_inst( "execution.log" );

#ifdef LOGGING_LEVEL_1

#define LOG log_inst.print< logging::severity_type::debug >
#define LOG_ERR log_inst.print< logging::severity_type::error >
#define LOG_WARN log_inst.print< logging::severity_type::warning >

#else

#define LOG(...) 
#define LOG_ERR(...)
#define LOG_WARN(...)

#endif

#ifdef LOGGING_LEVEL_2

#define ELOG log_inst.print< logging::severity_type::debug >
#define ELOG_ERR log_inst.print< logging::severity_type::error >
#define ELOG_WARN log_inst.print< logging::severity_type::warning >

#else

#define ELOG(...) 
#define ELOG_ERR(...)
#define ELOG_WARN(...)

#endif

#endif

Line 4 shows a static instantiation of the logger class. The logger is a template that needs to be parameterized with a logging policy. In this case, I'm using a file logging policy, which means that all the output of the logger will be directed to a file on the physical disk.

Lines 6-8 and 15-17 are where the logging macros are defined. As you can see, there are two logging levels (the second level may be enabled to have a more verbose output), and three severity levels. The preferred logging level may be enabled or disabled by toggling the LOGGING_LEVEL_x definition. When those macro definitions are absent, a log invocation attempt will be resolved by the preprocessor in the usage of the definitions visible at lines 10-12 and 19-21, which do no logging.

Listing Two shows an example of the logger usage and the relative output:

Listing Two: Example.

#define LOGGING_LEVEL_1
#include "logger.hpp"

int main()
{
   LOG("Starting the application..");
   for( short i = 0 ; i < 3 ; i++ )
   {
   LOG("The value of 'i' is ", i , ". " , 3 - i - 1 , " more iterations left ");
   }
   LOG_WARN("Loop over");
   LOG_ERR("All good things come to an end.. :(");
   return 0;
}

Output:

0000000 < Wed Jan 09 12:33:18 2013 - 0000005 > ~ <DEBUG> :Starting the application..
0000001 < Wed Jan 09 12:33:18 2013 - 0000005 > ~ <DEBUG> :The value of 'i' is 0. 2 more iterations left 
0000002 < Wed Jan 09 12:33:18 2013 - 0000005 > ~ <DEBUG> :The value of 'i' is 1. 1 more iteration left 
0000003 < Wed Jan 09 12:33:18 2013 - 0000005 > ~ <DEBUG> :The value of 'i' is 2. 0 more iterations left 
0000004 < Wed Jan 09 12:33:18 2013 - 0000005 > ~ <WARNING> :Loop over
0000005 < Wed Jan 09 12:33:18 2013 - 0000005 > ~ <ERROR> :All good things come to an end.. :(

The Logging Policy

Listing Three shows the policy interface and the implementation for the file policy, which uses a C++ ofstream to direct the log messages to the disk.

Listing Three: Log policy.

class log_policy_interface
{
       public:
       virtual void		open_ostream(const std::string& name) = 0;
       virtual void		close_ostream() = 0;
       virtual void		write(const std::string& msg) = 0;
};

class file_log_policy : public log_policy_interface
{
       std::unique_ptr< std::ofstream > out_stream;
    public:
        file_log_policy() : out_stream( new std::ofstream ) {}
        void open_ostream(const std::string& name);
        void close_ostream();
        void write(const std::string& msg);
        ~file_log_policy();
};

A logging policy should use a pure abstract class to describe how the interface for the policy works (line 5). This logger "policy" provides functionality related to the log writing, as the logger does not know where its output will be directed: Whether to disk, RAM, or even tunneled by a socket to a remote computer, it just calls a "write" function in the provided policy.


Related Reading


More Insights






Currently we allow the following HTML tags in comments:

Single tags

These tags can be used alone and don't need an ending tag.

<br> Defines a single line break

<hr> Defines a horizontal line

Matching tags

These require an ending tag - e.g. <i>italic text</i>

<a> Defines an anchor

<b> Defines bold text

<big> Defines big text

<blockquote> Defines a long quotation

<caption> Defines a table caption

<cite> Defines a citation

<code> Defines computer code text

<em> Defines emphasized text

<fieldset> Defines a border around elements in a form

<h1> This is heading 1

<h2> This is heading 2

<h3> This is heading 3

<h4> This is heading 4

<h5> This is heading 5

<h6> This is heading 6

<i> Defines italic text

<p> Defines a paragraph

<pre> Defines preformatted text

<q> Defines a short quotation

<samp> Defines sample computer code text

<small> Defines small text

<span> Defines a section in a document

<s> Defines strikethrough text

<strike> Defines strikethrough text

<strong> Defines strong text

<sub> Defines subscripted text

<sup> Defines superscripted text

<u> Defines underlined text

Dr. Dobb's encourages readers to engage in spirited, healthy debate, including taking us to task. However, Dr. Dobb's moderates all comments posted to our site, and reserves the right to modify or remove any content that it determines to be derogatory, offensive, inflammatory, vulgar, irrelevant/off-topic, racist or obvious marketing or spam. Dr. Dobb's further reserves the right to disable the profile of any commenter participating in said activities.

 
Disqus Tips To upload an avatar photo, first complete your Disqus profile. | View the list of supported HTML tags you can use to style comments. | Please read our commenting policy.
 

Comments:

ubm_techweb_disqus_sso_-bfaa326467b4eaf70c9af53fe5ba5a8e
2013-06-26T11:40:39

I'm late to the party, having just read this article, but I also have found fault with your implementation.

A problem with your design is that there is no way to instantiate a logger and then just use predefined LOG macros. The macros must be redefined in each project. That is error prone and verbose.

I'm struggling to understand the purpose of your second logging level. DEBUG-level logging is where I would expect verbosity. Why would I use ELOG_ERR vs. LOG_ERR or ELOG_WARN vs. LOG_WARN? The only thing I can imagine is that you choose to use LOG* for production releases, and ELOG* for additional logging in test builds, but can there really be much occasion for that difference of logging? I've not experienced it.

log_policy_interface needs a virtual destructor, since logger holds one by pointer, but I fail to see why that's so. Either hold the logger_policy object by value, or use CRTP to inherit from it. Both would eliminate the need for virtual functions, thereby improving performance.

There's no reason for file_log_policy to hold its ofstream via pointer. The free store allocation just adds another indirection.

Others have rightly suggested using lock_guard.

The variadic interface seems rather odd. Your policy design assumes an ostream, so why not expose it? Then, the logging would be insertions into an ostream. Using a macro, you can even conditionally stream based upon whether the logging level is enabled at runtime. The insertions would be the one macro argument, and would be inserted into the ostream, so all but the first value is preceded by <<:

LOG("The value of 'i' is " << i << ". "
<< (3 - i - 1) << " more iterations left ");

Your severity to prefix logic can be improved both by indexing an array and by avoiding multiple ostream insertion operations. One line does the job:

log_stream << '<' << severity_names[severity]
<< "> :";

Your logger class would be more efficient, too, if you exposed the ostream. Rather than calling functions that build and return strings which are then inserted into the stream, just pass in the ostream and build the output directly. The ostring_stream in get_logline_header() can be replaced by the real log ostream, which eliminates the ostring_stream and the string extracted from it.

There are a great many things that should be done to this design to truly earn the name lightweight.


Permalink
ubm_techweb_disqus_sso_-6b1d3f0f31e9d1e273c362fda4f39e5b
2013-02-05T16:50:05

I got many good ideas from the comments to my article. Actually i wish to remove at all the virtual dependency and apply a CRTP style polymophism or much more simply just forwarding the policy via a simple parameter.

Also some unefficient copy activities could be removed quickly.

About the syncronization issue, in my opinion the policy should be as simpliest as possible, as also shouldn't handle any sync procedure. but this of course, i just an opinion.

About the inheritance use, well, i'm not sure whether is proper to consider a 'logger' object as an extension of a policy 'is-a'. This could be an open space for further discussion.

When i get some free time ( maybe next weekend ) i want to upload the new logger to my github repository, allowing all to further improve/discuss the code.


Permalink
ubm_techweb_disqus_sso_-bf895e97be5bbc47aaa4d26454eb5c4e
2013-02-05T15:09:37

It seems to me that:
1. Using inheritance for the log policy would be shorter and faster than aggregation.
2. Synchronization should be pushed into the log policy, since some policy may not need it, for example windows log service.
What is your opinion?


Permalink
ubm_techweb_disqus_sso_-92154ddf32dbe56e514eaf7aa16fb7a0
2013-02-05T11:59:59

For the sake of correctness you should have defined a virtual destructor for log_policy_interface class.


Permalink
ubm_techweb_disqus_sso_-6b1d3f0f31e9d1e273c362fda4f39e5b
2013-02-02T14:19:36

Having the logger in a sperate thread from an accademic point of view is a interesting solution, is in my opinion not praticable in real applications, especially which are working on embedded systems.

Let's for example figure what will happen if the system crash before the concurrent queue is computed and flushed out, you'll lose the information provided by the logger, this can make impossible to troubleshoot the reason of the crash. And this is something you cannot explain easily to a customer ( And anyway, he will not accept your clarification )

Is better to have a logger which introduce a little overload but guarantee each print to be immedialy written down to a file.

Anyhow, i avoid consideration about the hardware on which the code runs, since is not guaranteed that will be excecuted on a ordinary computer. But if we ignore this possibility, then you pointed a good idea for further development.


Permalink
ubm_techweb_disqus_sso_-94da23943ddc4a858850e5d6f7bee9c8
2013-02-01T17:18:36

If I am not mistaken then when one uses a lock like you do you will cause all threads to wait until the io is complete. Once the mutex unlocks you will have context switches, not to mention the hardware will try to sync L1/2/3 caches for the loggers state.

Instead if you implement this logger as an active object which posts the logging messages to a concurrent queue that is being processed in a separate thread then you avoid waiting for the io to complete. Sure the queue is concurrent but the wait to enque and dequeue is significantly shorter than waiting for io to complete (especially unbuffered io).

Once the thread that is actually logging finishes writing to the stream there is a strong chance that a context switch will be avoided when it dequeues the next statement to log. Since only one thread is changing the state of the stream in the file_log_policy class you may also avoid some of the hardware cache syncing. You may not be able to avoid hardware cache sync for the concurrent queue though.


Permalink
ubm_techweb_disqus_sso_-d8e80bca7efa1f16cdb622acf6d20586
2013-02-01T14:32:21

Any chance of comparing to log4cxx (http://logging.apache.org/log4... This is a very powerful logger we've been using for a few years now, it is excellent.


Permalink
ubm_techweb_disqus_sso_-9d2d5fa0896b92878673be61524868c8
2013-02-01T10:05:32

I like the idea of using variadic templates for logging purposes but I see a few issues with your code:
1. You should use lock_guard as already stated. To improve speed on single threaded apps you could use locking policy here to provide compile time locking removal or you could use std::unique_lock with defer_lock for runtime locking removal based for example on "number of threads" command line parameter.
2. You used variadic templates in a way that may be highly inefficient because of copying of arguments. I assume you do not assume people will use std::ref() in a logger macro? I suggest using perfect forwarding here.
3. I really think that the output policies are not a right way to go here. At least with the interface you provided. Virtual functions make all the benefits of compile time inlining and optimizations go away. open_ostream, close_ostream make constructors and destructors useles. What 'name' would you provide for std::clog, std::cout or similar policy? I would suggest using properly used policies or even better a simple argument to logger constructor to pass output facility.
4. Using stringstream may be highly ineffcient here if you assume you work always (or mostly) with streams (at least it is what can be read from your policy interface). Maybe you should just use output stream directly by getting a reference to std::ostream from helper class?
5. In listing 9 I suggest removing '\n' inside time_str local variable and give a chance for RVO or move semantics to work instead of always copying the string body.


Permalink
ubm_techweb_disqus_sso_-6b1d3f0f31e9d1e273c362fda4f39e5b
2013-02-01T09:43:12

Well, i agree with you that as general rule is not necessary to check the value from the 'new' call. So in this case i was the paranoid one.

For your second question, ín my environment just the 'new' operator is not allowed to throw exceptions, that's the reason for the check. You're right this is not necessary is a standard compliant implementation ( but is indeed needed when applied to old code, where 'new' may not raise exceptions )

btw thanks for the observation.


Permalink
ubm_techweb_disqus_sso_-59808b4ad2992c6d71be783bfd834a8b
2013-02-01T09:10:46

I suppose it's difficult for me to comment on an unspecified compiler implementation that doesn't follow a defined C++ standard, but under a standards-conforming implementation at least, I don't believe that it's legal to return null from operator new (other than nothrow new). If using nothrow new, then a null check still won't catch the case where a constructor might throw, as operator new returning null only applies to the allocation of memory, not object construction.

For curiosity's sake, regarding disallowing exceptions, what will your compiler do with the throw statement on line 8? Will it produce a compiler error? If not, will it assert, do nothing, or do something else entirely if executed?


Permalink
ubm_techweb_disqus_sso_-6b1d3f0f31e9d1e273c362fda4f39e5b
2013-02-01T08:25:56

Should be sufficient to define in a separate .cpp the logger instance and make ‘extern’ the one in the .hpp to avoid this problem.

About your second comment, if the ‘new’ operator is overloaded and for some reason does not thrown an exception, the ‘if’ statement will catch the invalid pointer and will raise the exception, otherwise the standard std::bad_alloc will flow out of the constructor.

As sake of example the project where I work the exceptions are not allowed at all and the allocator which belong to ‘new’ just return nullptr in case of failed allocations, in this case not making this check can lead to catastrophic behaviors.


Permalink
ubm_techweb_disqus_sso_-6b1d3f0f31e9d1e273c362fda4f39e5b
2013-02-01T08:09:49

No you’re no. Is possible that kind of problem happen, and using std::lock_guard can prevent this. Anyhow the Achilles' heel should be in the ‘write’ function for the logger policy, if who implements this function does not guarantee the exception safety then using std::lock instead of std::lock_guard can be problematic. Thanks for the finding.


Permalink
ubm_techweb_disqus_sso_-59808b4ad2992c6d71be783bfd834a8b
2013-02-01T07:59:52

In Listing One, why is there a static log_inst object defined per-translation unit? Won't each .cpp file then have it's own logger with it's own corresponding state? Won't there be undesirable effects if multiple objects (and multiple threads) write to the same file unsynchronized? Note that I'm not familiar with Windows programming, so perhaps there are platform-specific file I/O guarantees that I am not aware of. In any case, the log line numbers will not be synchronized across objects.

As mentioned previously, I agree that it would be better to use std::lock_guard, as using discrete lock and unlock calls are fragile in the presence of exceptions (and return statements).

Finally, note that there appears to be a bug in Listing Ten. The data member policy will never be null on line 6 as the result of a new/allocation failure on line 5. As a consequence, the throw on line 8 will never be executed.


Permalink
ubm_techweb_disqus_sso_-2238e364495b3c6e05d98585337cad73
2013-01-31T19:03:43

I'm sure the templating can catch issues during compile time, but what if it couldn't and it had an exception parsing the variadics (or even invalid pointer during runtime), wouldn't you get the MUTEX to stay locked and blocks the other thread for ever? Would it be ideally better to wrap it with std::lock_guard? Am I being too paranoid?


Permalink

Video