Creating Thread Safe Logger

[SCass2010]

Hi everyone,

Again, I'm just trying stuff out to try and learn a bit more but here goes...

I created a small Logger util - I included the pthread library and added a mutex lock in each of the "write*" functions, tested it by running a few instances of a test program, each printing "hello world" 100,000 times to the same file the it seems to work - no lines were cut off or anything, and each instance seemed to wait it's turn... thing is, is it really this easy to make a thread safe logger?

How I plan on using it was say in the main () of my program, create a logger like

Log* myLogger = new Log ();

Then for each object/whatnot that needs logging, pass that pointer into it so it's all logging to the same place and so on.

Also, I'm sure someone has asked this a thousand times so sorry in advance! but how would you go about making the logger work like the stringstream class i.e.

myLogger->writeInfo () << "Log messages " << count << " Times";

Any help or comments would be much appreciated :)

[SCass2010]

Log.h

#ifndef LOG_H
#define LOG_H

#include <fstream>
#include <stdarg.h>
#include <iostream>
#include <pthread.h>

#define INFO    "Info :"
#define WARNING "Warn :"
#define ERROR   "Error:"
#define DEBUG   "Debug:"

using namespace std;

class Log
{
    public:
        Log (char* logFilename, bool debugOn = false);
        virtual ~Log ();
        void writeInfo (const char* logline, ...);
        void writeWarn (const char* logline, ...);
        void writeError (const char* logline, ...);
        void writeDebug (const char* logline, ...);
    private:
        pthread_mutex_t mLock;

        char*           getTimeStamp ();
        ofstream        mStream;
        bool            mDebugOn;
};
#endif

Log.cpp

#include "Log.h"
#include <stdarg.h>

Log::Log (char* logFilename, bool debugOn)
    : mDebugOn (debugOn)
{
    pthread_mutex_init (&mLock, NULL);
    mStream.open (logFilename, fstream::app);
}

Log::~Log ()
{
    mStream.close ();
    pthread_mutex_destroy (&mLock);
}

void Log::writeInfo (const char* logline, ...)
{
    pthread_mutex_lock (&mLock);
    va_list argList;
    char    buffer [1024];
    
    va_start (argList,
              logline);

    vsnprintf (buffer,
               1024,
               logline,
               argList);

    va_end (argList);

    mStream << getTimeStamp () << " Info  : " << buffer << endl;
    cout << getTimeStamp () << " Info  : " << buffer << endl;
    pthread_mutex_unlock (&mLock);
}

void Log::writeError (const char* logline, ...)
{
    pthread_mutex_lock (&mLock);
    va_list argList;
    char    buffer [1024];
    
    va_start (argList,
              logline);

    vsnprintf (buffer,
               1024,
               logline,
               argList);

    va_end (argList);

    mStream << getTimeStamp() << " Error : " << buffer << endl;
    cout << getTimeStamp() << " Error : " << buffer << endl;
    pthread_mutex_unlock (&mLock);
}


char* Log::getTimeStamp ()
{
    char*           tString = new char [80];
    time_t          t       = time (0);
    struct  tm*     today   = localtime (&t);

    strftime    (tString,
                 80,
                 "%d/%m/%Y %H:%M:%S",
                 today);
    return tString;
}

[Fortran IV]

Using a mutex to make things “thread safe” is actually pretty easy. That is what they are designed to do. However, keep in mind, the purpose of a mutex is to protect a Resource, generally some sort of data storage element. You protect Operations (that is sections of executable code) by creating multiple instances of the code, not with a mutex. Usually, you want the Lock and Unlock as close together as possible, ideally just around the actual access to the resource. And, it is bad karma to call other functions within a locked block (be careful even calls to system functions…). For example, in your code, I would move the calls to getTimeStamp outside of the loecked region. Also, just make a single call. You don’t really want to have different times in the log and on the output. Be careful that you don’t use nested mutexes unless you know EXACTLY what you are doing. For example, this can happen when you put a lock around a call to an access function to get a value. If the access function also has a lock around the value (not necessarily the same mutex), you have created a nested lock. This will fail sometimes (or every time if you are lucky. Intermittent lock problems are a pain).

Remember, being inside of a locked region does not guarantee the code will not be interrupted! It just means that no other task using the same mutex can execute past where it tries to get the mutex. If low priority task “A” is in a locked region, and higher priority task “B” starts, A will block and B can run until it tries to get the mutex locked by A. Does A restart then? Maybe – but it is possible that task “C” may start first. Hopefully, C does not need a resource locked by B…

[SCass2010]

Hi,

Thanks for the reply - I guess I was expecting it too be alot more complicated! I see what you mean about the getTimeStamp, I thought since it was called at the same as the write* function it would need to be included in it, but I see now I was probably making pointless calls to it when I could get it in one go lol :P

[varungandhi]

I have also got some thing same in c++ i did a sample project using critical section but have never used mutexes can you give some help if i post code snippet here.

Thanks