Class Level Generic Logger

• Download source code - 2.4 KB

Abstract

This article explains class level generic logger that provides feasibility to log at class level where each class can have separate messages, logging level and output strategy. Application using logging API, in order to log the messages, would remain unaffected while the changes in class details like logging messages, logging level and output strategy can be controlled from a separate logging module making application code unrelated (decoupled) with the class related information. This is generic in the sense application code remains the same whereas logging messages, logging level and logging output changes as per the user need, without affecting the application code.

Overview

This article is about class level generic logger. Class level in the sense logging messages, logging level and output strategy (example, output to File, Console, etc.) for each class would be different and generic in the sense programs calling logging API in order to log their messages would not contain the class related logging detail. Class specific logging data, logging level and output strategy shall be configurable externally. It allows each class to mix class specific data along with actual log data whereas logging strategy can be different in different contexts. Logging can happen in syslog way, to a local file, to remote machine or to a separate GUI window, etc. In normal logger logging data completely comes from program code making it difficult to have custom description related to the class embedded in the log text. If someone needs to have class related data, then in each log text, it would be required to push class related information making it tedious to code.

Problem

In logging mechanism, typically three things are required, class specific data in log, logging at different levels and able to send data to different targets. All three things should be achieved generically and without changing the code in order to make one combination to other.

Scenario

Considering different output per class/module, programmer has to push class related messages in each logging message and if there are too many logging messages per class, then it is difficult to type similar messages while calling logging API. Considering various levels of logging (warning, info, error), a programmer should differentiate logging per level and user should find a way to set a level of logging so that some logging level messages can be masked. Level should be set at class level and each class should be able to mask the messages separately. Considering various targets for log, a programmer has to use a different API for each type of output strategy, for example logging to console it is iostream, ofstream for logging to a file, sockets for logging to different machine, GUI API for logging inside a separate GUI window. So no way this way of three coordinates are generic. Programmer is carrying all the burden of handling different combinations differently.

Solution

A generic solution is to have programmer code static and a helper class should be provided in order to make combinations take place at runtime. The solution proposed here is to have separate logger abstraction which provides logging API to log at different levels. Different targets are achieved through strategy where target is abstraction in logger and data (and level) per class is achieved through visitor pattern where a class carry function overloading for each class and calling these function confirms the level and embeds a class specific information in the log data. Design look would be as given below.

Design

                             +---------------------+
                             |    config           |-------
                             +---------------------+      |<<reads>>
                             | enum LogLevel{i,w,e}|      |
                             | readconfig(string&,m|      v
                             |  ap<string,pair<logl|   ------------
                             |  evelir<,message> >)|  / config.txt|
------------------           +---------------------+  -------------
| gostringstream |                 ^
------------------                 |
        ^                          |
        |<<nested>>                +------------------+
       (+)                                            |
+---------------+       <<visitor>>            +---------------+
| logger        |<>--------------------------> | visitor       |
+---------------+                              +---------------+
| visit:visitor*|                              | loglevel:level|
| policy:policy*|                              +---------------+
| message:gostri|                              | visit(classA) |
|   ngstream    |<>-----+                      | visit(classB) |
+---------------+       |                      +---------------+
| visitr():vister|      |                            / \
| stratgy():stragegy|   |                             -
+---------------+       |                             |
                        |                +------------+------
                        |                |            | . . .
                        |        +--------------+  +---------------+
                        |        | infovisitor  |  | verbosevisitor|
                        |        +--------------+  +---------------+
                        |        | visit(classA)|  | visit(classA) |
                        |        | visit(classB)|  | visit(classB) |
                        |        +--------------+  +---------------+
                        |
                        |
                        |  <<strategy>>      +------------------+
                        +------------------> | strategy         |
                                             +------------------+
                                             |print(string&)=0; |
                                             +------------------+
                                                     / \
                                                      -
                                                      |
                                      +---------------+-----------------+-------
                                      |               |                 |. . .
                               ----------------  ------------------  -------------------
                               | filestrategyy|  | consolestrategy|  |guiwindowstrategy|
                               ----------------  ------------------  -------------------

Code

The main logger class looks like:

class logger {
  class gostringstream{
  public:
  gostringstream(logger* lp):loggr(lp){};
  gostringstream& operator<<(std::ostream& (*)(std::ostream&)){
    ostrstrm<<std::endl;
    return *this;
  }
  template<typename T>
  gostringstream& operator<<(const T& typep){
    ostrstrm<<typep;
    return *this;
  }
  gostringstream& operator<<(void (*)()){
    ostrstrm<<std::endl;
    loggr->print(ostrstrm);
    ostrstrm.str("");
    return *this;
  }
  const std::ostringstream& str(){return ostrstrm;}
  public:
  std::ostringstream ostrstrm;
  logger* loggr;
  };
  void print(const std::ostringsteam& datap) {strat->print(datap);}
  public:
  gstringstream& strstrm(){return message;}
  visitor* visitr() {return visit;}
  strategy* stratgy() {return strat;}
  ~logger(){
    print(message.str());
    delete strat;
    delete visit;
  }
  static logger& getlogger(){
    static logger l;
    return l;
  }
  private:
  logger():strat(new consolestrategy), visit(new infovisitor), message(this){};
  gostringstream message;
  strategy *strat;
  visitor *visit;
};

It composes classes with visitor and strategy design pattern. It uses a config class to maintain log level and to provide log level and message related configuration detail from a config file. visitor class is responsible for checking the level of log message, if it is permissible to log in the context of a class, then it provides the message content to be added in against each message. strategy class takes the message and prints it to a device, where device specific detail is provided through subclass of strategy at run time.

class config {
  enum LogLevel{i,w,e};
  public:
  typedef LogLevel loglevel;
  static const loglevel INFO = i;
  static const loglevel WARN = w;
  static const loglevel ERRO = e;
  static const char* ltos(loglevel lp) {
    if(lp == i)  return "INFO";
    else if(lp == w) return "WARN";
         else return "ERRO";
  }
  LogLevel stol(const std::string& levelname) {
    if(levelname == "INFO") return INFO;
    else if(levelname == "WARN") return WARN;
         else return ERRO;
  }
  config(const std::string& rfilenamep,
  std::map<std::string, std::pair<loglevel, std::string> >& rmapp) {
    std::string line, classname, levelname, message;
    std::ifstream instrm(rfilenamep.c_str());
    if(!instrm) return;
    else
    while(getline(instrm,line)) {
      if(std::string::npos==line.find_first_not_of(" \t"))continue;
      std::istringstream strstrm(line);
      strstrm>>classname>>levelname>>message;
      message+=line.substr(strstrm.tellg());;
      rmapp[classname]=make_pair(stol(levelname),message);
    }
  }
};

Here, readconfig is called when visitor class is getting constructed, this would read configuration file in order to have log level and message filled against each class. This data structure is maintained by visitor class in std::map. Other information config class provides is Loglevel enums and function to convert level to string. Config file layout is, each line has tokens classname, loglevel and messages, each separated by spaces or tabs. Loglevel is as per defined by config::loglevel(INFO,WARN,ERRO).

config.txt

classA   INFO    classA(http handler)
classB   WARN    classB(database handler)


  ^       ^               ^
  |       |               |
  \       \           class specific message
   \   class specific level

 class name

Here, config.txt has entries for two classes, classA and classB. classA logs at INFO level (all messages at level INFO and above) whereas classB logs at WARN level (WARN or above). classA provides log string "classA(http handler)" whereas classB provides "classB(database handler)". visitor base class provides abstract methods (visit) in order to place class specific messages which is implemented through its derived class, i.e., infovisitor. If config.txt does not provide class level messages, then it looks for message hard coded as default in visitor class, failing to get that makes no special message for the class.

class visitor {
  public:
  visitor():level(config::INFO),con("config.txt",slmp){};
  const char* format(config::loglevel levelp,const char* datap) {
    char uls[16];
    struct timeval currenttime;
    struct tm *btime;
    if(!gettimeofday(¤ttime,NULL)) {
      btime=localtime(¤ttime.tv_sec);
      sprintf(uls,"%d:%d:%d.%u %s %s ",btime->tm_hour,btime->tm_min,btime->tm_sec,
         currenttime.tv_usec,config::ltos(levelp),datap);
    }
    else
    sprintf(uls,"time not known");
    return ((std::string)(uls)).c_str();
  }
  virtual const char* visit(classA*,config::loglevel)=0;
  virtual const char* visit(classB*,config::loglevel)=0;
  virtual const char* visit(void*,config::loglevel)=0;
  virtual ~visitor(){};
  protected:
  config::loglevel level;
  std::map<std::string, std::pair<config::loglevel,std::string> > slmp;
  config con;
};

Here, visitor abstract class provides abstract methods visit per each class. In constructor, it instantiates config which internally prepares data structure map after reading config.txt file. It also provides library function format which reads message to be printed and inserts time (microsecond granularity) information to the message. Visitor class either includes class specific headers files or makes a forward declaration of all classes that served through its visit methods. It maintains a global (default) log level which is provided to each visit in case a class follows global loglevel rules. For class specific levels and messages, it maintains table (std::map) of each class row containing columns for log level and message against the class. visitor class is further sub classed in order to provide one type of behavioural aspects. infovisitor class provides short description about the class whereas verbosevisitor provide verbose information.

class infovisitor:public visitor {
  public:
  const char* visit(classA*,config::loglevel levelp) {
    const char* classmsg="class A";
    if(slmp.count("classA")) {
      level=slmp["classA"].first;
      classmsg=slmp["classA"].second.c_str();
    }
    if(levelp<level) return NULL;
    else return format(levelp, classmsg);
  }
  const char* visit(classB*,config::loglevel levelp) {
    const char* classmsg="class B";
    if(slmp.count("classB")) {
      level=slmp["classB"].first;
      classmsg=slmp["classB"].second.c_str();
    }
    if(levelp<level) return NULL;
    else return format(levelp, classmsg);
  }
  const char* visit(void*,config::loglevel levelp) {
    if(levelp<level) return NULL;
    else return format(levelp, "");
  }
};

Here, visit method keeps default message and default level, once message and level is found in the map structure (from config.txt) file, new values takes into effect. As mentioned earlier, strategy class is responsible to print the final data to some device.

class strategy {
  public:
  virtual void print(const std::ostringstream&)=0;
  virtual ~strategy(){};
};

strategy class just provides a print function in order to print its string argument to an abstract device. Concrete devices are provided through its sub classes which initializes the device in its constructor and provides actual device printing. consolestrategy prints data to console output.

class consolestrategy:public strategy {
  public:
  void print(const std::ostringstream& rstrp){std::cout<<rstrp.str();}
};

filestrategy prints data to file system.

class filestrategy:public strategy {
     public:
     filestrategy():ofile("log.txt",std::ofstream::out|std::ofstream::app){}
     void print(const std::ostringstream& rstrp){ofile<<rstrp.str();}

     private:
     std::ofstream ofile;
   };

It prints data to log.txt file. Message member variable of logger actually takes message from the user, get messages from visitor mixed in it, then finally pushes its string to strategy for device output. Messages are pushed to message member variable, of type gostringstream (wrapper over std::ostringstream), through macros provided to the users. Macro are divided in two parts first for static or non class member function calls and second for non static class members which have legal this pointer.

#define LOG(x,y) \
if(const char *p=logger::getlogger().visitr()->visit(x,y))logger::getlogger().strstrm()<<p
#define NLOGI \
LOG((void*)NULL,config::INFO)
#define NLOGW \
LOG((void*)NULL,config::WARN)
#define NLOGE \
LOG((void*)NULL,config::ERRO)
#define LOGI \
LOG(this,config::INFO)
#define LOGW \
LOG(this,config::WARN)
#define LOGE \
LOG(this,config::ERRO)
#define EL (void (*)())NULL

NLOG macros are necessary for functions that do not have legal this pointer (non object members) and LOG macros are for object member functions. These macros are further divided into log levels as LOGI is for logging at INFO level. LEND macro is delimiter to make final move to push the messages to device and to clear the buffer.

Usage

From any class member (non static) function, logger macros LOGI, LOGW and LOGE can be called whereas non class functions and static member function can call NLOG macros. User needs to include lh.h file in the assembly unit (.h, .cc) files where logging is required. User can then directly call LOG APIs followed by EL macro to give a hint to finally place the messages to devices. For example, classA and classB are classes where logging is required. Then, in classA and classB member functions, user needs to call LOGI, LOGW, LOGE for making logger log at INFO, WARN and ERRO level respectively. For example:

#include "lh.h"   <----- include lh.h
class classA {
  public:
  classA(){
  LOGI<<"default constructor"<<std::endl;
  }
  void init() {
  int i=0;
  LOGI<<__FUNCTION__<<" begin"<<EL;
  LOGE<<"connection failed"<<EL;
  for(i=1;i<4;i++) {
  LOGW<<"making number "<<i<<" attempt"<<EL;
  }
  LOGI<<__FUNCTION__<<" end"<<std::endl;
  }
  ~classA(){LOGI<<"getting destructed, bye!!";}
};
#include "lh.h"    <------ include lh.h
class classB {
  public:
  classB(){
  LOGI<<"default constructor"<<EL;
  }
  void init() {
  int i=0;
  LOGI<<__FUNCTION__<<" begin"<<EL;;
  LOGE<<"connection failed"<<EL;
  for(i=1;i<4;i++) {
  LOGW<<"making number "<<i<<" write attempt"<<std::endl;
  }
  LOGI<<__FUNCTION__<<" end"<<EL;
  }
  ~classB(){LOGI<<"getting destroyed, bye!!"<<std::endl;}
};

The main.c file includes classA.h and classB.h.

#include "classA.h"
#include "classB.h"
int main() {
  NLOGI<<"int main()"<<EL;
  classA a;
  classB b;
  a.init();
  b.init();
  return 0;
}

config.txt has information.

classA    INFO    classA(httphandler)
classB    WARN    classB(database)

where classA logs at INFO level and classB at WARN level.

Logger constructor:

logger():strat(new filestrategy), visit(new infovisitor){};

constructs filestrategy which pushes data to log.txt file.

>>cat log.txt                       +-------class specific message
15:52:59.9178401 INFO int main()    v
15:52:59.918101l INFO classA(http handler) default constructor
15:52:59.918362l INFO classA(http handler) init begin
15:52:59.918432l ERRO classA(http handler) connection failed
15:52:59.918455l WARN classA(http handler) making number 1 attempt
15:52:59.918492l WARN classA(http handler) making number 2 attempt
15:52:59.918509l WARN classA(http handler) making number 3 attempt
15:52:59.918526l INFO classA(http handler) init end
15:52:59.918548l ERRO classB(database) connection failed
15:52:59.918566l WARN classB(database) making number 1 write attempt
15:52:59.918584l WARN classB(database) making number 2 write attempt
15:52:59.918600l WARN classB(database) making number 3 write attempt
15:52:59.918623l INFO classA(http handler) getting destructed, bye!!
                                               ^
                                               |
                             general message(from programmer's code)

Here classA logs at all levels (INFO, WARN, ERRO) where as classB logs at level (WARN, ERRO).

Performance

TEST HAS BEEN CONDUCTED ON 1000 CLASSES. IT IS DIVIDED AMONG TWO CATEGORIES, EACH CLASS PROCESSING 100 MESSAGES I) EACH CLASS ITERATING QUEUE MESSAGES 100 TIMES II) EACH CLASS ITERATING QUEUE MESSAGES SINGLE TIME AND 1000 CLASS IS ITERATED 100 TIMES.

1. Each class 100 messages.
   1. Each message is pushed to filesystem(unbuffered) at the time of write, 100000 writes. 5 runs. 571807, 575958, 578076, 604675, 578819 usec, average 581867 usec - speed 171k/s
   2. Each class cache the 100 message and then flush to file system, 1000 writes. 5 runs. 554542, 528969, 527111, 537700, 527536 usec, average 535171 usec - speed 186k/s
   3. Completely buffered and single write to file system at the end. 5 runs. 511325, 509211, 516344, 514364, 514177 usec, average 513084 usec, speed 194k/s
2. Each class 1 message, 100 iteration for 1000 classes.
   1. Each message is pushed to file system(unbuffered) at the time of write, 100000 writes. 5 runs. 634328, 636556, 640491, 632451, 635717 usec, average 635908 - speed 157k/s
   2. 1000 messages, one for each class cached and written in a go to filesystem, total 100 writes. 5 runs. 578221, 579069, 577274, 577791, 576807 usec, average 577832, speed 173k/s
   3. Completely buffered and single write to file system at the end. 5 runs. 573315, 577246, 593168, 573472, 572119 usec, average 577864, speed 173k/s

200  |                                  (194)
     |                                    *
190  |                 (186)
     |                   *
180  |                 (173)            (173)
     |  (171)            +                +
170  |     *
     |
160  |   (157)
     |     +
150  |
 ^   |
 |   |                    * 100 loop each class
speed|                    + 100 loop for 1000 class
in   |
K/s  |
for  |
1000 |
class|
     ------------------------------------------
        Unbuffered      1000/100       Buffered
                        writes

So if each message is flushed to device, then it performs 171k messages per 1000 class. This would be considered high volume.

Further Addition

There are few points that can be covered. If a base and derive class pointer is passed to visitor, then candidates would be ambiguous. This can be resolved in having visit for base class pointer function inside pointers can be dissociated to separate class through static_cast<derive*>. logger class right now logs to one device for every class, this can further be generalized in order to each class have freedom to choose its own device. This choice can be provided through config file. Right now, logging is done with considering not thread safe. Thread safe can be made when strategy::print function would be called after mutex lock is acquired whereas upon strategy::print function returns mutex lock would be released by the calling thread. Boost library and C++ 0X provides mutex.

Summary

Class level generic logger is a logger which can log to any log level to any device and can put messages at class level granularity. Users have choice to tweak these options against each class in config file. Programmers using logger just need to include lh.h and then start firing.