Problem
Every application logs a whole bunch of diagnostic messages, primarily for (production) debugging, to the console or the standard error device or to files. There are so many other destinations where the logs can be written to. Irrespective of the destination that each application must be able to configure, the diagnostic log message and the way to generate the message is of our interest now. So we are in need of a Logger class that can behave transparent to the logging destination. That should not be a problem, it would be fun to design that.
The crux of the problem now is the generation of the log messages. Usually the log messages are generated dynamically in your code. For instance if a user calls an API int GetFileSize(LPCTSTR lpszFilePath), the log may look something like this:
GetFileSize - File: C:\Temp\Sample.txt. Size: 1492 bytes.
In the above line of log, the file path and size values are known at runtime depending on the file. And the log could also bear the current date and time with the current logged in user requesting the file size and a variety of other stuff that might look information rich to the user. So, no doubt, our logger should have a method with variable number of arguments. Let us do the first draft of our Logger class.
class Logger
{
public: Logger() ;
public: ~Logger() ;
public: void LogMessage(const std::string& category, const std::string& fmtSpec, ...);
};
The variable number of arguments is just fair enough. The C/C++ style of format specification string is cryptic with % and tough to match the corresponding format specification for each type; and especially tough when the format specification string is a long one. For instance, in order to output an int, the format specifier must be %d; if the programmer made a mistake by specifying %s, the whole show comes down. The application crashes pathetically. That is our prime problem to be solved - type safe logging.
So:
- Our logger must offer type safe logging, which means there must literally be no possibility of crash due to format specification mismatch or improper arguments count.
- The C++ programming language and the Windows operating system both do not offer a convenient and generic logging facilities.
- The
Logger must be loosely coupled with the log destination. - The variable arguments facility is very crude and something a C programmer would be happy about, whereas C++ abstracts and encapsulates everything as objects.
Solution - (Type Safe) Logger
The first obstacle to get through is the facility to specify the variable number of arguments, especially in a type safe way. Fortunately the Standard Template Library is our savior. We can rely on std::ostringstream cutie for generating messages on the fly. A quick look:
std::ostringstream ostr;
ostr << "GetFileSize - File: " << filePath.c_str() <<
"\tSize: " << fileSize << "bytes.";
The message thus constructed can be then directed to any destination - file, standard error, UI etc. That is the core of our solution.
However the message construction must be based on a format specification. One good advantage of a format specification is that it gives a world view of the message that would be constructed\logged; while on the other hand, it is cryptic to read and know the message from a std::ostringstream construct as above. That means we are thinking of blending and innovating a Logging construct which involves printf-like format specification with std::ostringstream. Although we seem to have solved the variable arguments problem, we are back to square on the format specification. Our aim is to get rid of the world where %ld has to be matched for a numeric or %s for a string. For that matter, even std::ostringstream's << operator does not do good with a parameter that is a std::string.
If that is our pain, then let us devise our own format specification, which provides type safety. By type safety, we aim to never crash at runtime and also detect specification anomalies. So let us use the .NET style of format specification which uses argument index placeholders but the format specifier still is %. So for our GetFileSize example, the format specification string may look like the following:
"GetFileSize - File: %0. Size: %1 bytes. User: %2. Is '%0' read-only: %3"
By now, you must be saying wow! First good thing in the above format specification string is the repeating index placeholders (%0), which avoids specifying duplicate arguments. The other good things will be discussed in a short while.
We are ready with our format specification design - format specification and variable arguments. Now we need to merge these to construct messages on the fly. We need a way (via methods or such) to pass in the format specification, followed by argument passing. Besides that, we must be able to do log level based logging. That means I must be able to pass in the format spec and arguments, and use the LogMessage method. May be our Logger usage could be:
Logger x("GetFileSize - File: %0. Size: %1 bytes. User: %2. Is '%0' read-only: %3");
x << "C:\\Temp\\Sample.txt" << 2945 << Visitor << "True";
x.LogMessage();
Horrible, Isn't it? By doing it the ugly way, we realize there is an elegant way.
Logger().LogMessage("GetFileSize - File: %0. Size: %1 bytes.
User: %2. Is '%0' read-only: %3")
<< "C:\\Temp\\Sample.txt" << 2945 << Visitor << "True";
OR
Logger().LogMessage("Failed to get file size!");
That is how our logging construct is going to be. We create and log in a single line of code. Our Logger class will be overloading the << operator to intake the arguments passed, and will be making the use of the destructor to log to the desired destination right after the line where logging is done. Why destructor? Since we rely on C++'s promise that it will destroy temporary objects after the current statement where it is created completes execution. Well, that is the time we actually need the logging to take place, isn't it?
Where Do We Log?
As we discussed earlier, our Logger is transparent to the logging destination. And for that reason, we intend to keep the part of physical logging out of the Logger class. The Logger class makes use of a user defined type, TLogWriter (a template argument), that actually logs the string to the desired destination. The Logger class's main responsibility is to format the log message as per the format specification and then log the message using TLogWriter type.
template <typename TLogWriter > class Logger
{
private: std::string _fmtSpec;
private: TLogWriter& _logWriter;
typedef typename TLogWriter::TLogMetaData TLogMetaData;
private: TLogMetaData _logState;
public: Logger(TLogWriter& gWriter, const std::string& fmtSpec,
TLogMetaData logState) : _formatSpec(fmtSpec),
_logState(logState),
_logWriter(gWriter)
{
}
public: virtual ~Logger()
{
std::string streamText = PrepareStream();
_logWriter(streamText, _logState);
}
protected: std::string PrepareStream();
private: template<typename T> Logger& operator <<(T t);
};
The users are required to define the TLogWriter type which should actually perform the physical logging in the format desired. For ease of use, log writers that log to standard error device and file are provided in the download.
The TLogWriter type has some pre-requisites:
- A
typedef that describes the metadata that needs to be passed to the log writer during logging (example Category, ThreadID, etc.) - Definition of a
() operator with the following prototype std::string operator()(const std::string& msgText, TLogMetaData lmData)
One of the reasons for having a separate TLogWriter type is to abstract the meta-data information required during logging from the Logger class. By doing this, we also get the benefit of not requiring to derive from the Logger class and use the Logger class readily. The Logger class can now easily adapt itself to any user-defined TLogWriter type that fulfills the pre-requisites mentioned above.
'What if I am not interested in the log metadata? I just want to log the formatted string to the destination.' You can modify the Logger class to get rid of TLogMetaData. We leave this option to the user since from our experience most of the logging requires meta-data.
Examples and Use
Let us try writing a TLogWriter that logs to the standard error device.
struct LogMetadata
{
LogLevel eLevel; LogCategories eCategory; std::string ThreadInfo;
public: LogMetadata(LogLevel eLevel, LogCategories eCategory,
const std::string& threadInfo)
: eLevel(eLevel), eCategory(eCategory), ThreadInfo(threadInfo)
{
}
};
class StdErrorWriter
{
public: typedef LogMetadata TLogMetaData;
public: StdErrorWriter()
{
}
private: static std::string CurrentDateTimeToString();
private: static std::string ToString(LogCategory);
private: static std::string ToString(LogLevel);
public: std::string operator()(const std::string& msgText, TLogMetadata lmData)
{
std::ostringstream ostr;
ostr << "[" << CurrentDateTimeToString() << "] [" <<
ToString(lmData.Category) << "] [" << ToString(lmData.LogLevel) <<
"] " << msgText << std::endl;
std::string logText = ostr.str();
::OutputDebugString(logText.c_str());
}
};
Following is the way to use the above writer in code:
int _tmain()
{
std::vector files = GetFiles();
StdErrorWriter seWriter;
for (size_t i = 0; i < files.size(); ++t)
{
int size = GetFileSize(files[i]);
Logger<StdErrorWriter>(seWriter,
"GetFileSize - File: %1.%0Size: %2.%0",
LogMetadata(LOGLEVEL_INFO, LOGCGTRY_APPDB, CurrentThreadInfoText()))
<< "...." << files[i] << size;
}
}
In the above use of writer, you may even create it as a temporary object as follows since it does not have any state information.
Logger<StdErrorWriter>(StdErrorWriter(),
"GetFileSize - File: %1.%0Size: %2.%0",
LogMetadata(LOGLEVEL_INFO, LOGCGTRY_APPDB, CurrentThreadInfoText()))
<< "...." << files[i] << size;
But if the writer writes to the file, then it is not wise to create it as a temporary object since it might involve opening and closing the file for each line of log. Refer attached source for the implementation of FileLogWriter.
Highlights
The format specification (%n) considers only % followed by n as the indexed place holder, where n is any number in the range 0-256. Any other character after the % is not given any special treatment and is directed to the logging destination; except a % (after %) is for logging a %, like a \\ in C style logging. In short, a %% is an escape sequence for %.
Unlike the C style, when there is a need for displaying an argument more than once, the format specification can refer by the argument index (%n) several times and specify the argument only once, which avoids specifying duplicate arguments.
Since Logger overloads '<<' operator and internally relies on std::ostringstream, any argument in essence should be a string-convertible. All simple types are identified and automatically converted to string for logging. For complex types and special logging formats, the user supplies the formatted string. For instance, if I want to log my class, I may (have to) provide a ToString method on the class that gives me the string representation of the class, which is not an unfair thing.
Since we used custom format specification with %, there is no possibility of argument-type mismatch, and no crashes due to the same. Besides, any argument passed that is not string-convertible results in a compiler error, which is one of the biggest benefits.
The argument count mismatch is safely handled avoiding runtime crashes. If the number of arguments passed (via <<) is less than the number of argument placeholders (%n), then asserts are issued for each argument placeholder for which the corresponding argument is not found, and the %n is directly logged. For instance, in the following line of log, %2 is asserted for argument mismatch and the string '%2' is logged.
Logger(StdErrorWriter(), "GetFileSize - File: %1.%0Size: %2.%0",
LogMetadata(LOGLEVEL_INFO, LOGCGTRY_APPDB, CurrentThreadInfoText()))
<< "...." << files[i];
So argument mismatches can be identified and resolved during compile time without doubt.
All arguments passed beyond the required number of arguments are appended to the generated log message.
Limitations
The Logger has been designed to be created and used as a temporary object. It is not designed to be created as a named object. The rationale behind that is that the trigger for logging is based on the destructor and we would want the messages to be logged appear right away, and not when the (named) object goes out of scope. Although there are ways by which that can be accomplished, most cases of logging are solved with the current design.
Although the specification is half .NET style, our Logger does not offer all formatting facilities - hex, spacing, etc. All such things are kept outside of the Logger. This was not intentional but we thought to start the Logger simple. So if you want to output a number in hex, the ToHexString static method of the Logger class may be used.
Logger("Hex number: %0", Logger::ToHexString(1000));
The maximum number of arguments that can be specified (in the format spec) is 256. At the time of writing this logger for my application, there was no chance of having a format spec with more than 256 arguments. Besides, I thought a Logger that allows constructing a format spec with 256 arguments may be fancy enough but from a practical stand-point, reading and getting a world of view of the message is not that easy, and the purpose is beaten. However, for people who opine otherwise, this limitation can be easily gotten rid of by making a few (minor) modifications in the code.
Happy Logging!
History
- 7 APR 2009 - Initial version
- 20 APR 2009 - Modified the design to abstract the writer logic as
TLogWriter type with log metadata which would be specified by the TLogWriter - 11 MAY 2009 - Updated source code
