Thread safe operator<<

Question

I have a quite complicated problem with my logger class. Its is a singleton pattern logging class. A thread is created only for taking out items from queue and logging them. Generally everything works fine and the error occurs very occasionally as segmentation fault. It was happening even more often before I decided to put a mutex on whole method chain. With that mutex i dont understand why is the segmentation fault occuring. The class got quite complicated because of the operator<< usage. Problem with it is that the operator template is run as many times, as many items are passed using <<. Because of that other threads can cut in between those templete calls.

The general usage looks like this: 1. instance method is called (creating or pointing to the instance pointer (singleton). mutex is locked at this moment. 2. any called methods are called, for example operator<< template. 3. finishing method is called, placing log in the queue and unlocking mutex.

I have edited the code and tried to take the fata gathering out of the singleton class to the proxy class.

main.c:

#include <iostream>
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>

#include "CLogger.h"
#include "CTestClass.h"

using namespace std;

int main()
{
    CLogger::instance().log.startLog("/home/lukasz/Pulpit/test.txt", true);
    CLogger::instance().log.setLogLevel(CLogger::ElogLevel::eDebug);

    CLogger::instance().printf("Print test");
    CLogger::instance().printf("Print test");
    CLogger::instance().printf("Print test");
    CLogger::instance() << "Stream test" ;
    CLogger::instance() << "Stream test" ;
    CLogger::instance() << "Stream test" ;


    //CTestClass test1(1);
    //CTestClass test2(2);
    //CTestClass test3(3);

    sleep(3);
    CLogger::instance().log.stopLog();

    return 0;
}

CLogger.h:

#ifndef CLOGGER_H_
#define CLOGGER_H_

#include <iostream>
#include <deque>
#include <string>
#include <mutex>
#include <condition_variable>
#include <pthread.h>
#include <ostream>
#include <fstream>
#include <sstream>
#include <ctime>
#include <iomanip>
#include <sys/time.h>
#include <stdarg.h>
#include <assert.h>

#include "CTeebuf.h"

using namespace std;

class CLoggerProxy;

/*!
 * \brief Singleton class used for logging
 */
class CLogger
{
public:
    /*!
     * \brief Describes the log level of called \ref CLogger object.
     */
    enum class ElogLevel { eNone = 0, eError, eWarning, eInfo, eDebug };

    /*!
     * Structure describing a single log item:
     */
    struct logline_t
    {
        string logString; /*!< String line to be saved to a file (and printed to cout). */
        ElogLevel logLevel; /*!< The \ref ElogLevel of this line. */
        timeval currentTime; /*!< time stamp of current log line */
    };

    static CLogger* internalInstance(ElogLevel lLevel = ElogLevel::eDebug);
    static CLoggerProxy instance(ElogLevel lLevel = ElogLevel::eDebug);

    bool startLog(string fileName, bool verbose);
    void setLogLevel(ElogLevel ll);
    void stopLog();
    void finaliseLine(logline_t* log);

protected:
    virtual void threadLoop();

private:
    CLogger() {};                               // Private so that it can  not be called
    CLogger(CLogger const&) {};                 // copy constructor is private
    CLogger& operator= (CLogger const&) {};     // assignment operator is private

    /*!< Global static pointer used to ensure a single instance of the class */
    static CLogger* mp_instance;
    bool m_logStarted;
    ElogLevel m_userDefinedLogLevel;
    ofstream m_logFileStream;
    bool m_verbose;
    bool m_finishLog;
    timeval m_initialTime;

    static void * threadHelper(void* handler)
    {
        ((CLogger*)handler)->threadLoop();
        return NULL;
    }

    deque<logline_t*> m_data;
    mutex m_mutex2;
    condition_variable m_cv;
    pthread_t   m_thread;

    logline_t pop_front();
    void push_back(logline_t* s);
};

/*!
 * RAII class used for its destructor, to add a log item to the queue
 */
class CLoggerProxy
{
public:
    CLogger &log;
    CLoggerProxy(CLogger &logger) : log(logger)
    {
        mp_logLine = new CLogger::logline_t;
        gettimeofday(&mp_logLine->currentTime, NULL);
    }

    ~CLoggerProxy() { log.finaliseLine(mp_logLine); }

    void printf(const char* text, ...);

    /*!
     * Takes the data from the stream and adds it to the current string.
     * @param t stream item
     * @return \ref object address
     */
    template <typename T>
    CLoggerProxy& operator<< (const T &t)
    {
        ostringstream stream;
        stream << t;
        mp_logLine->logString = (stream.str() + " ");
        return *this;
    }

private:
    CLogger::logline_t* mp_logLine;

};

#endif /* CLOGGER_H_ */

CLogger.cpp:

#include "CLogger.h"

using namespace std;

CLogger* CLogger::mp_instance = NULL;

/*!
 *  This function is called to create an instance of the class.
 *  Calling the constructor publicly is not allowed. The constructor
 *  is private and is only called by this Instance function.
 *  @param lLevel  Log level for current object
 */
CLogger* CLogger::internalInstance(ElogLevel lLevel)
{
    // Only allow one instance of class to be generated.
    if (!mp_instance)
    {
        mp_instance = new CLogger;
        assert(mp_instance);
    }

    return mp_instance;
}

/*!
 * This method is called in order to use the methods
 * within the objects.
 * @param lLevel  Log level for current object
 */
CLoggerProxy CLogger::instance(ElogLevel lLevel)
{
    return CLoggerProxy(*internalInstance(lLevel));
}

/*!
 * \brief Starts the logging system.
 *
 * This method creates and opens the log file,
 * then opens it and creates the threadloop for messages deque.
 * @param fileName desired log file path,
 * @param verbose when set true, logging will also be printed to standard output.
 */
bool CLogger::startLog(string fileName, bool verbose)
{
    if(remove(fileName.c_str()) != 0)
        perror( "Error deleting file" );

    m_logFileStream.open(fileName.c_str(), ios::out | ios::app);
    if (!m_logFileStream.is_open())
    {
        cout << "Could not open log file " << fileName << endl;
        return false;
    }

    m_finishLog = false;
    m_verbose = verbose;
    m_logStarted = true;
    gettimeofday(&m_initialTime, NULL);

    return (pthread_create(&(m_thread), NULL, threadHelper, this) == 0);
}

/*!
 * \brief puts a \ref logline_t object at the end of the queue
 * @param s object to be added to queue
 */
void CLogger::push_back(logline_t* s)
{
    unique_lock<mutex> ul(m_mutex2);
    m_data.emplace_back(move(s));
    m_cv.notify_all();
}

/*!
 * \brief takes a \ref logline_t object from the beggining of the queue
 * @return first \ref logline_t object
 */
CLogger::logline_t CLogger::pop_front()
{
    unique_lock<mutex> ul(m_mutex2);
    m_cv.wait(ul, [this]() { return !m_data.empty(); });

    logline_t retVal = move(*m_data.front());

    assert(m_data.front());
    delete m_data.front();
    m_data.front() = NULL;

    m_data.pop_front();

    return retVal;
}

/*!
 * \brief Sets the log level for the whole \ref CLogger object.
 * If \ref m_logLine is equal or higher than set level, log
 * is going to be printed.
 * @param lLevel desired user define log level.
 */
void CLogger::setLogLevel(ElogLevel lLevel)
{
    m_userDefinedLogLevel = lLevel;
}

/*!
 * \brief Stops the logging system.
 * Last final logline is being added and then the logging thread
 * is being closed.
 */
void CLogger::stopLog()
{
    m_finishLog = true;
    //instance(ElogLevel::eNone).log << "CLogger Stop";

    //pthread_join(m_thread, NULL);
}

/*!
 * This function should be run in the \ref CLoggerProxy destructor.
 * is pushes the gathered stream to the queue.
 */
void CLogger::finaliseLine(logline_t* log)
{
    if (log->logString.size() > 0)
        push_back(log);
    else
        delete log;
}

/*!
 * \brief Adds text log to the string in the printf c way.
 * Works faster than operator<< and its more atomic.
 * @param text pointer to a character string.
 * @param ... argptr parameters
 */
void CLoggerProxy::printf(const char* text, ...)
{
    va_list argptr;
    va_start(argptr, text);

    char* output = NULL;
    vasprintf(&output, text, argptr);

    mp_logLine->logString = output;
    va_end(argptr);
}

/*!
 * The loop running in a separate thread. It take items of the
 * log deque object (if there are any) and saves them to a file.
 */
void CLogger::threadLoop()
{
    logline_t logline;
    const string logLevelsStrings[] = {"eNone", "eError", "eWarning", "eInfo", "eDebug" };

    COteestream tee;
    tee.add(m_logFileStream);

    if (m_verbose)
        tee.add(cout);

    struct sched_param param;
    param.__sched_priority = 0;

    if(!sched_setscheduler(0, SCHED_IDLE, &param))
        instance().printf("Clogger scheduler policy set to %d", sched_getscheduler(0));

    int secs = 0;
    int h = 0;
    int m = 0;
    int s = 0;

    do
    {
        logline = pop_front(); // waits here for new lines

        secs = logline.currentTime.tv_sec - m_initialTime.tv_sec;
        h = secs / 3600;
        m = ( secs % 3600 ) / 60;
        s = ( secs % 3600 ) % 60;

        tee     << "["
                << setw(2) << setfill('0') << h
                << ":"
                << setw(2) << setfill('0') << m
                << ":"
                << setw(2) << setfill('0') << s
                << "."
                << setw(6) << setfill('0') << logline.currentTime.tv_usec
                << "]"
                << "["
                << setw(2) << setfill('0') << m_data.size()
                << "]"
                << "["
                << logLevelsStrings[(int)logline.logLevel]
                << "] "
                << logline.logString << "\n" << flush;
    }
    //while(!(m_finishLog && m_data.empty()));
    while(1);

    m_logFileStream.close();
}

Answer 1

There are several problems with your code.

Singleton

// Only allow one instance of class to be generated.
if (!mp_instance)
{
    mp_instance = new CLogger;
    assert(mp_instance);
}

This is a classic problem. It may be called by different threads at the same time, and it is not thread safe. You may end up with several instances of your singleton.

The queue (m_data)

Clients of your logger put their messages into this queue (apparently secured by m_mutext).

m_data.emplace_back(move(s));
m_cv.notify_all();

Your logger thread removes the messages in its own thread (secured by m_mutex2).

unique_lock<mutex> ul(m_mutex2);
m_cv.wait(ul, [this]() { return !m_data.empty(); });

logline_t retVal = move(*m_data.front());

assert(m_data.front());
delete m_data.front();
m_data.front() = NULL;

m_data.pop_front();

return retVal;

The problem here is, you use 2 different mutexes to synchronize access to the same object. This cannot work.

In addition you access m_data in your thread without any locking at all:

            << setw(2) << setfill('0') << m_data.size()

or

while(!(m_finishLog && m_data.empty()));

The log message (mp_logLine)

You try to lock too much data. The pointer to your log message is meant to be used by a single thread at a time. But you store it in the main logger class which is accessed by all threads. You already have a proxy for your logger which is private to the thread using it. Store your message there until it's finished, and then add it to the queue.

Generally said, minimize the amount of data to be locked. If you rework your code and the only object needing locking is your queue, you are on the right way.

Answer 2

This doesn't look threadsafe at all.

mp_logLine->logString += (stream.str() + " ");

This looks like it's shared between all threads that log to an instance. It's not clear from your code that += is thread safe.

Another point is when you push back an item into your queue you don't lock the mutex. If two threads are doing it at the same time they can mess up the deque. There's no guarantee that you can do push_back and pop_front in parallel, so put a mutex around it.

When you get an internal instance you lock mp_instance->m_mutex but it doesn't look like you're unlocking it.

You use bool m_logStarted from parallel threads and that can also introduce race conditions and inconsistencies.

Any of the above can cause your segmentation fault.

Getting multi-threading right is really hard. Debugging it is even harder. Try to offload the multi-threading component(s) to a library you know already works and add things in a single threaded context. In this case it would mean to use a separate class instance for every call to the log and then push the item to a producer-consumer queue that's implemented by some library and guaranteed thread-safe. There are many other ways to do it as well.