LoggingFrameworkProposal

Logging Framework Enhancement Proposal

This is a proposal to change the way that debug, warning and error message logging is done in Box Backup.

Challenge

The way that logging is currently done is inconsistent, confusing, inflexible and broken:

• Uses printf(...) in some places, fprintf(stderr, ...) in others, and syslog(...) in others
• Infinite TRACE macros for debugging messages that can't easily be enabled in a release build
• No way to change the verbosity level at runtime
• No integration with Windows event log, results in duplicated code
• printf/fprintf messages cannot be seen when running Box Backup as a service under Windows
• Conversely, when running Box in the foreground, all messages should go to the console instead of syslog
• Some event log messages under Windows are split in two, because one function calls another and neither has all the information required
• Boxi cannot suppress and redirect Box Backup's messages into the GUI
• Warnings about which files are not being backed up are not accessible anywhere except in syslog
• Unless you have root access to the box running Box, you have no access to important logs in syslog
• printf(), fprintf() and syslog() all use varargs, which is dangerous and not cross-platform compatible

Logging for analysis and billing

When a message is attributable to a specific account, or includes a 'relevant figure' such as bytes in or out, it should be separated from the message content. If the logging back end is a database, these numbers can be stored in separate columns, so a well choosen SQL query can yeild lots of useful information about the behaviour of the system or a client.

Proposal

Implement a BOX_LOG(level, stuff) macro using iostreams:

#define BOX_LOG(level, stuff) \
{ \
    if(Log::sMaxLoggingLevelForAnyOutput >= level) \
        std::ostringstream line; \
        line << stuff; \
        Log::Log(level, <ul>FILE</ul>, <ul>LINE</ul>, line.str()); \
    } \
}

Macros BOX_TRACE, BOX_INFO, BOX_WARNING, BOX_ERROR, BOX_FATAL which supply the level argument to BOX_LOG. BOX_TRACE is completely compiled out of release builds, unless an option is given to the configure script to enable them.

#define BOX_FATAL(stuff)   BOX_LOG(Log::FATAL, stuff)
#define BOX_ERROR(stuff)   BOX_LOG(Log::ERROR, stuff)
#define BOX_WARNING(stuff) BOX_LOG(Log::WARNING, stuff)
#define BOX_INFO(stuff)    BOX_LOG(Log::INFO, stuff)
#if defined NDEBUG && ! defined COMPILE_IN_TRACES
        #define BOX_TRACE(stuff)   
#else
        #define BOX_TRACE(stuff)   BOX_LOG(Log::TRACE, stuff)
#endif

An abstract Logger class with the following methods:

bool Log(level_t level, std::string file, std::string line, std::string message);
void Filter(level_t level);

Logger::Filter() sets the minimum level that will be logged by the Logger. It will be possible to set the level differently for each output method. Rationale: If you run box with "increased verbosity" from the command line, you probably want more detail on the console, but not necessarily in the syslog/Windows event log. Similarly for a command-line "quiet" option.

If Logger::Log returns false, then logging stops at that point, otherwise it proceeds to the next logger. This allows a temporary suppression or redirection logger to be pushed onto the stack.

Implementations of Logger for console and syslog (Logger::Console and Logger::Syslog).

The Log class contains a private static std::vector of enabled loggers, which can be added and removed with static methods like ToSyslog(), ToConsole(), Add() and Remove():

class Log
{
        private:
        static std::vector<Logger> mActiveLoggers;

        public:
        static void ToSyslog  (bool);
        static void ToConsole (bool);
        static void FilterConsole (level_t);
        static void FilterSyslog  (level_t);
        static void Add    (Logger&);
        static void Remove (Logger&);
        static void Log(level_t level, std::string file, std::string line, std::string message);
        typedef enum { FATAL = 1, ERROR, WARNING, INFO, TRACE } level_t;
        static void SetContext(std::string context);
        static void ClearContext();
}

The SetContext method is used to set a string that is prepended to all log messages sent by the current process, until ClearContext is called. This will be used by the store daemon to tag all messages relating to a specific account with the account number, in housekeeping and client-handling processes. SetContext may not be called a second time without calling ClearContext first, and vice versa.

A critical section on Win32 to prevent the vector of loggers from being concurrently modified and used.

Replace all instances of printf(), fprintf(), syslog() and TRACEx with either calls to the BOX_* macros, or iostreams.

Alternate Proposal (Richard Hurt)

Why not use log4c http://log4c.sourceforge.net/? It has most of the features you mention above plus a community of developers behind it, people are familiar with it, and it's already been designed. One of the things I really like about it is that you can turn logging up/down without recompiling. That means that if someone is having trouble with something, you can edit a text file and have them increase the logging on their own system. The other really nice thing about it is that you can hook it into different logging facilities (syslog, Windows Error, etc.) using different appenders. You can also completely customize the output at runtime.

It just looks like to me that we are recreating something that already exists.

My reasons for not using log4c (chris):

• It's C, and the rest of Box is C++, makes an ugly mix (and yes, I know about log4cxx)
• The ability to compile out TRACE messages completely was demanded by Ben (to ensure zero overhead on embedded systems)
• We don't actually need a lot of features of other logging frameworks (as far as we know)
• What we do need is easy to implement
• It's already implemented
• It's very lightweight
• It does allow changing logging levels on the fly
• It already had redirectors for console, syslog and Windows event log
• No text files required (all controlled from the command line)
• No additional dependencies
• We understand it completely
• It's easy to debug
• It does exactly what we need, or we can make it do it
• Avoids format specifications which are dangerous and not portable
• The real work is in rewriting the Box code to use the framework (new macros), not in writing the framework (it's done)
• Once the Box code has been thus converted, it would be trivial to switch to log4c(xx) or any other logging framework