My program doesn't support thread safe logging

Question

I am currently creating a class that should be used for logging purpose.

But here one problem , it doesn't support thread synchronization. There is no problem when I run one by one thread. But there is problem while I run two or more threads at a time.

Problem I am facing is: "If I create two threads to create two separate logs , but Two threads are colliding and write its log messages to both the files".

If anyone find the problem , please help me to resolve it.

BoostLogger.h :

#pragma once
......
///////////////////////////////////////
//Defining Macros
///////////////////////////////////////
#define AddCommonAttr()         logging::add_common_attributes()
#define GetLoggingCore()        logging::core::get()
#define LoggingSeverity         logging::trivial::severity
#define AddFileLog              logging::add_file_log
#define ThreadValueType         logging::attributes::current_thread_id::value_type
#define Record                  logging::record
#define Extract                 logging::extract

#define ExprStream              expr::stream
#define ExprAttr                expr::attr
#define ExprFormatDateTime      expr::format_date_time
#define PosixTimeType           boost::posix_time::ptime
#define ExprMessage             expr::smessage

#define FileName                keywords::file_name
#define RotationSize            keywords::rotation_size
#define TimeBasedRotation       keywords::time_based_rotation
#define Format                  keywords::format
#define Target                  keywords::target
#define MaxSize                 keywords::max_size
#define MinFreeSpace            keywords::min_free_space
#define RotationAtTimeInterval  sinks::file::rotation_at_time_interval

#define Reset_Filter            reset_filter                                /*The reset_filter method removes the global logging filter.*/
#define Set_Filter              set_filter                                  /*The set_filter method sets the global logging filter to every log record that is processed.*/
#define SetFormatter            set_formatter
#define RecordView              logging::record_view
#define FormattingOstream       logging::formatting_ostream
#define SharedPtr               boost::shared_ptr
#define MakeShared              boost::make_shared
#define SinkFileBackend         sinks::text_file_backend
#define LockedBackend           locked_backend
#define SetFileCollector        set_file_collector
#define MakeCollector           sinks::file::make_collector
#define AddSink                 add_sink                                    /*The add_sink method adds a new sink. The sink is included into logging process immediately after being added and until being removed. No sink can be added more than once at the same time. If the sink is already registered, the call is ignored.*/
#define RemoveSink              remove_sink                                 /*The remove_sink method removes the sink from the output. The sink will not receive any log records after removal. The call has no effect if the sink is not registered.*/
#define RemoveAllSinks          remove_all_sinks                            /*The remove_all_sinks method removes all registered sinks from the output. The sinks will not receive any log records after removal.*/
#define Flush                   flush
#define ScanForFiles            scan_for_files
#define ScanAll                 sinks::file::scan_all
#define ScanMatching            sinks::file::scan_matching

#define SetExceptionHandler     set_exception_handler
#define ExceptionSuppressor     logging::make_exception_suppressor
#define MakeExceptionHandler    logging::make_exception_handler

typedef sinks::synchronous_sink < SinkFileBackend >     sink_type;

static src::logger lg;
#define WriteToLog              BOOST_LOG(lg)

/*Defining Macros for Writing log with Severity*/
//BOOST_LOG_INLINE_GLOBAL_LOGGER_DEFAULT(my_logger, src::logger_mt)
//static src::severity_logger< logging::trivial::severity_level > slg;

#define LogTrace        BOOST_LOG_SEV(obj->slg, logging::trivial::trace)        
#define LogDebug        BOOST_LOG_SEV(obj->slg, logging::trivial::debug)        
#define LogInfo         BOOST_LOG_SEV(obj->slg, logging::trivial::info)     
#define LogWarning      BOOST_LOG_SEV(obj->slg, logging::trivial::warning)  
#define LogError        BOOST_LOG_SEV(obj->slg, logging::trivial::error)        
#define LogFatal        BOOST_LOG_SEV(obj->slg, logging::trivial::fatal)        
#define _1MB    (1 * 1024 * 1024)
#define _10MB   (10 * 1024 * 1024)
#define datefmt ("_%Y-%b-%d")
#define timefmt ("_%H-%M-%S")

using namespace std;
class CBoostLogger
{
private: 
    SharedPtr< SinkFileBackend > backend;
    SharedPtr< sink_type > sink;
public:
    src::severity_logger< logging::trivial::severity_level > slg;
    CBoostLogger(void);
    ~CBoostLogger(void);
    bool StartLogger(struct FileFormat *sff);
    bool StopLogger();
    bool SetFilter(short severitylevel);
    bool SetFormat(struct LogFormat *sle);

private:
    friend void Formatter(logging::record_view const& rec, logging::formatting_ostream& strm);
};
/*This Structure is used to set the formats for file*/
struct FileFormat
{
bool includedatetofile;
bool includetimetofile;
string filename;
string filelocation;
unsigned long rotationsize;
unsigned long maxsize;

FileFormat() :  includedatetofile(false),
                includetimetofile(false),
                filename("log")         ,
                filelocation("C:/Log")  ,
                rotationsize(_1MB)      ,
                maxsize(_10MB)          {};
};

struct LogFormat
{
bool Set_LineID;
bool Set_Time;
bool Set_Severity; 
bool Set_ThreadID;
bool Set_Message;

LogFormat() :   Set_LineID(true)    ,
                Set_Time(true)      ,
                Set_Severity(true)  ,
                Set_ThreadID(true)  ,
                Set_Message(true)   {};

LogFormat(bool lineid, bool time, bool severity, bool threadid, bool message) 
    :   Set_LineID(lineid)      ,
        Set_Time(time)          ,
        Set_Severity(severity)  ,
        Set_ThreadID(threadid)  ,
        Set_Message(message)    {};
};

BoostLogger.cpp:

#pragma once
#include "BoostLogger.h"

////////////////////////////////////
//Global Declarations
////////////////////////////////////

bool SetLineID, SetTime, SetSeverity, SetThreadID, SetMessage ;

CBoostLogger::CBoostLogger(void)
{
    cout << "Calling CBoostLogger Constructor..." << endl;
    SetFilter(2);
    //GetLoggingCore()->SetExceptionHandler(MakeExceptionHandler<std::runtime_error,std::exception>(handler()));
    GetLoggingCore()->SetExceptionHandler(ExceptionSuppressor());
}

CBoostLogger::~CBoostLogger(void)
{
    GetLoggingCore() -> Reset_Filter();     
    GetLoggingCore() -> RemoveAllSinks();
}

bool CBoostLogger::StartLogger(struct FileFormat *sff )
{
    if(sff->includedatetofile)
        sff->filename += datefmt;
    if(sff->includetimetofile)
        sff->filename += timefmt;
    sff->filename += ".log";
    backend = MakeShared < SinkFileBackend >(
                FileName            =   sff->filename,                                                                                  /*< file name pattern >*/
                RotationSize        =   sff->rotationsize                                                                               /*< rotate files for every 1M >*/
                );  
    sink = MakeShared < sink_type > (backend);
    LogFormat sle;
    SetFormat(&sle);
    sink->LockedBackend()->SetFileCollector
        ( 
            MakeCollector
            ( 
                Target  =   sff->filelocation ,                 /*File Storage Location*/   
                MaxSize =   sff->maxsize                        /*Limit for folder : maxsize, where initially maxsize = 10M*/
            )
        );
    sink->LockedBackend()->ScanForFiles(ScanAll);
    GetLoggingCore()->AddSink(sink);

    AddCommonAttr();    
    BOOST_LOG_SEV(this->slg, logging::trivial::info) << "Logger Starts";
    return true;
}

/*This function used to remove the registered sink from core.*/
bool CBoostLogger::StopLogger()
{
    BOOST_LOG_SEV(this->slg, logging::trivial::info) << "Logger Stops";
    GetLoggingCore()->RemoveSink(sink);
    GetLoggingCore()->Flush();
    return true;
}

    /*This function is used to set filter level. */
bool CBoostLogger::SetFilter(short severitylevel)
{
    GetLoggingCore()->Set_Filter                
    (
        LoggingSeverity >= severitylevel
    );
    return true;
}

/*This function is used to set format for log. */
bool CBoostLogger::SetFormat(struct LogFormat *sle)
{
    SetLineID   = sle->Set_LineID;
    SetTime     = sle->Set_Time;
    SetSeverity = sle->Set_Severity;
    SetThreadID = sle->Set_ThreadID;
    SetMessage  = sle->Set_Message;
    sink->SetFormatter(&Formatter);
    return true;
}

/*This function is used to set format for the log file.*/
void Formatter(RecordView const& rec, FormattingOstream& strm)
{
    if(SetLineID)   
    {
        strm << Extract < unsigned int >    ("LineID", rec) << "\t";    // Get the LineID attribute value and put it into the stream
    }
    if(SetTime) 
    {
        strm << Extract < PosixTimeType >   ("TimeStamp", rec) << "\t"; // Get the TimeStamp attribute value and put it into the stream
    }
    if(SetSeverity) 
    {
        strm << "[ " << rec[LoggingSeverity] << " ]\t";                 // Get the Severity attribute value and put it into the stream
    }
    if(SetThreadID) 
    {
        strm << Extract < ThreadValueType > ("ThreadID", rec )<<"\t";   // Get the ThreadID attribute value and put into the stream
    }
    if(SetMessage)  
    {
        strm << rec[ExprMessage];                                       // Finally, put the record message to the stream
    }
}

struct handler
{
  void operator()(const runtime_error &ex) const
  {
    std::cerr << "\nRuntime_error: " << ex.what() << '\n';
  }

  void operator()(const exception &ex) const
  {
    std::cerr << "Exception: " << ex.what() << '\n';
  }
};

Source.cpp :

#include "BoostLogger.h"

void func_thread(std::string fn,string fl,int num)
{
    std::string buf = "";
    char str[20];
    buf += itoa(num, str, 10);
    fn += buf;

    CBoostLogger *obj = new CBoostLogger();
    FileFormat formatobj;
    formatobj.filename = fn;
    formatobj.filelocation = fl;
    formatobj.includedatetofile = true;
    formatobj.includetimetofile = true;
    obj->StartLogger(&formatobj);

    for(int i=0;i<10000;i++)
    {
        LogTrace    << "Trace message new " << fn;
        BOOST_LOG_SEV(obj->slg,logging::trivial::trace) << "Test";

        LogDebug    << "Debug Message new"  << fn;
        LogInfo     << "Info  message" << fn;
        LogWarning  << "Warning  message new" << fn;
        LogError    << "An error  message new" << fn;
        LogFatal    << "A fatal  message new" << fn;
    }   

    LogFormat sle(true,false,false,false,true);
    obj->SetFormat(&sle);   

    for(int i=0;i<10000;i++)
    {
        LogTrace        << "Trace message new " << fn;
        LogDebug        << "Debug Message new"  << fn;
        LogInfo     << "Info  message" << fn;
        LogWarning  << "Warning  message new" << fn;
        LogError        << "An error  message new" << fn;
        LogFatal        << "A fatal  message new" << fn;
    }   
    obj->StopLogger();
    delete obj;
}

int main()
{
    //This following code makes problem.
    boost::thread *thread1 = new boost::thread(&func_thread,"Thread_","C:/BoostLog",1);
    boost::thread *thread2 = new boost::thread(&func_thread,"Thread_","C:/BoostLog",2);
    thread1->join();
    thread2->join();

    /*
    //This following is not making that problem.
    boost::thread_group t_groups;
    for(int i=1;i<=5;i++)
    {
        t_groups.create_thread(boost::bind(&func_thread,"Thread","C:/BoostLog",i));
        t_groups.join_all();
    }

    boost::thread_group tgroup;
    boost::thread *threads;
    for(int i=0;i<20;i++)
    {
        threads=new boost::thread(&func_thread,"Thread","C:/BoostLog",i);
        tgroup.add_thread(threads);
        std::cout << "\nThread "<<i<<" is created whose id is : "<<threads->get_id();
        threads->join();
    }   
    */

    return 0;
}   

If you need anymore information regarding this, please ask me.

I want to create thread safe logger using boost library. Help me if you can.

And another one thing , if possible threads must run concurrently.

Thanks.

Answer 1

Being in a position of needing to do low latency logging from multiple threads I've recently done a bit of hunting around.

Basic Requirement

As far as I'm concerned a basic requirement is that the time to log an event should be fixed, and the shorter the better. A lot of the "multi-threaded" logging options I've seen fall down on this (log4cpp, boost mt loggers so far as I can tell).

A single logger that has a mutex of some sort embedded in it to ensure thread safety is not providing each thread using it with a guaranteed maximum logging time. When one thread tries to log it may be that there's a dozen other threads all contending on the same mutex. So thread safe doesn't scale up and also guarantee low latency.

The Ideal

What's needed is something where the logger is always available to the thread, events are stuffed into some sort of queue, and there's a separate thread at the other end pulling events off the queue and writing them to file or whatever.

Apache log4cpp

Apache log4cpp gets close to this - it has an AsyncAppender. I say close; whilst it has the back end thread calling whatever other appenders one has attached, the front end cannot be shared between a bunch of threads without them all fighting over the same mutex. But at least the act of writing to file is decoupled from logging. This goes a long way towards ensuring that a thread isn't blocked by a log.

Log4cpp

Log4cpp has a BufferingAppender (not mentioned in the docs, but it's there in the code). This has a queue, but no dispatcher thread like log4cxx's AsyncAppender. This could be used as a template to build something better.

Boost Log

This is a nasty horrible big ugly pile of hard to fathom and incompletely documented code. I've not yet been able to fathom out exactly what it can actually do vis a vis threads and my ideal, but I think that its asynchronous_sink does the job. Like Apache log4cxx it looks like the logging front end also uses a mutex to make it thread safe.

ZeroMQ

The problem I see with Log4cxx and Boost log is that there's not much room for logging architectural flexibility. What I really want is the type of patterns you can do with ZeroMQ.

I'm becoming convinced that I need to write my own logging library. ZeroMQ has some very nice patterns (particularly PUB/SUB), and using this to push log messages from threads to a central logging thread would seem to be a neat idea, especially given ZeroMQ's architectural flexibility.

The ZeroMQ sockets would act as buffers to soak up sudden logging demand, whilst the central thread plods along writing it all to disk. Provided the sustained rate of logging doesn't exceed the harddrive bandwidth it'll be fine.

I may try to squeeze it into log4cpp and literally use it as a transport between per thread category/appenders, and a central appender that does the actual output. This is going to be slightly tricky though. ZeroMQ transports bytes, not objects. So I may have to serialise log4cpp events... This then raises the question of what serialisation to use, etc. etc. and before I know it it'll become a nasty big inefficient monster.

Answer 2

In order to collision use

BOOST_LOG_ATTRIBUTE_KEYWORD(tag_attr, "Tag", std::string)
or
BOOST_LOG_SCOPED_THREAD_TAG("Tag", tag_)

For more details, you can check it below here :

Boost.log: How to prevent the output will be duplicated to all added streams when it uses the add_file_log() function?
By, Thiyagu

Answer 3

I'm not sure what you mean by "two threads colliding" but the first immediate problem with your code is that you're using non-thread-safe loggers src::logger and src::severity_logger. The thread-safe counterparts are src::logger_mt and src::severity_logger_mt (see here, for example).

If you want to separate logs generated by different threads into different files, you can try using the text_multifile_backend with the file name generator based on the "ThreadID" attribute, which you're adding by the logging::add_common_attributes() call in your initialization code. There's an example in the linked page.

By the way, you shouldn't call logging::add_common_attributes() every time CBoostLogger::StartLogger is called, which happens in every thread. The attributes need to be added only once.

An alternative solution, since you're creating CBoostLogger for every thread, is to set up a filter for the sink CBoostLogger::StartLogger adds. The filter has to pass records that have the current thread's id and discard the rest. You can do it like this:

bool CBoostLogger::StartLogger(struct FileFormat *sff )
{
    // ...
    sink = MakeShared < sink_type > (backend);

    // Get the current thread id
    typedef logging::attributes::current_thread_id::value_type thread_id;
    thread_id id = logging::attributes::current_thread_id().get_value().extract_or_throw< thread_id >();

    // Set the filter
    sink->set_filter(expr::attr< thread_id >("ThreadID") == id);

    // ...
}

If you want to improve concurrency of your code, you can try avoiding the global loggers in your code. Instead, create non-thread-safe loggers in a thread-local storage. Depending on your language version, you could use either thread_local or boost::thread_specific_ptr. Take note that in the latter case you have to ensure that the logger is initialized before its first use. In some cases it is also possible to keep the logger on the thread's stack.

Answer 4

I would recommend looking into boost::scoped_lock scoped lock documentation If you just want to make each function thread safe use a scoped lock with a mutex member variable. However if you want to synchronize your threads and the running of them look into boost::condition_variable