Question

I've been looking around at various approaches to the problem of threadsafe logging, but I haven't seen anything quite like this, so I dunno if it's somehow awful that I haven't noticed due to being a complete newbie to C++, threads and iostreams. It seems to work in the basic tests I've put it through.

Basically I have a Log class (creative, I know...) which has operator<< set up for the standard manipulators, so I can merrily pass in whatever I want.

However, I am aware that something like:

std::cout << "Threads" << " will" << " mess" << " with" << "this." << std::endl;

will potentially get interleaved when multiple threads are writing to cout (or wherever the Log ostream points). So, I have created some manipulators specific to the Log class that let me do this:

Log::log << lock << "Write" << " what" << " I" << " want" << std::endl << unlock;

I just want to know if this is an inherently awful idea, bearing in mind that I am willing to accept that users of the Log class will need to be disciplined with 'lock' and 'unlock'. I considered making 'std::endl' automatically unlock, but that just seems like it would create more headaches... I think undisciplined use should come out in testing anyway, but if anyone can see a way to make such uses cause compile-time errors, that would be nice.

I'd also appreciate any suggestions as to making my code any cleaner.

Here's a cut down version of the class for demonstration purposes; the whole thing has a few more constructors taking stuff like filenames, so not really relevant to the question.

#include <iostream>
#include <thread>
#include <fstream>

class Log{
public:
  //Constructors
  Log(std::ostream & os);
  // Destructor
  ~Log();
  // Input Functions
  Log & operator<<(const std::string & msg);
  Log & operator<<(const int & msg);
  Log & operator<<(std::ostream & (*man)(std::ostream &)); // Handles manipulators like endl.
  Log & operator<<(std::ios_base & (*man)(std::ios_base &)); // Handles manipulators like hex.
  Log & operator<<(Log & (*man)(Log &)); // Handles custom Log manipulators like lock and unlock.
  friend Log & lock(Log & log); // Locks the Log for threadsafe output.
  friend Log & unlock(Log & log); // Unlocks the Log once threadsafe output is complete.
private:
  std::fstream logFile;
  std::ostream & logStream;
  std::mutex guard;
};

// Log class manipulators.
Log & lock(Log & log); // Locks the Log for threadsafe output.
Log & unlock(Log & log); // Unlocks the Log once threadsafe output is complete.

void threadUnsafeTask(int * input, Log * log);
void threadSafeTask(int * input, Log * log);

int main(){
  int one(1), two(2);
  Log log(std::cout);
  std::thread first(threadUnsafeTask, &one, &log);
  std::thread second(threadUnsafeTask, &two, &log);
  first.join();
  second.join();
  std::thread third(threadSafeTask, &one, &log);
  std::thread fourth(threadSafeTask, &two, &log);
  third.join();
  fourth.join();
  return 0;
}

void threadUnsafeTask(int * input, Log * log){
  *log << "Executing" << " thread '" << *input << "', " << "expecting " << "interruptions " << "frequently." << std::endl;
}

void threadSafeTask(int * input, Log * log){
  *log << lock << "Executing" << " thread '" << *input << "', " << "not expecting " << "interruptions." << std::endl << unlock;
}

// Constructors (Most left out as irrelevant)
Log::Log(std::ostream & os): logFile(), logStream(logFile), guard(){
  logStream.rdbuf(os.rdbuf());
}

// Destructor
Log::~Log(){
  logFile.close();
}

// Output Operators
Log & Log::operator<<(const std::string & msg){
  logStream << msg;
  return *this;
}

Log & Log::operator<<(const int & msg){
  logStream << msg;
  return *this;
}

Log & Log::operator<<(std::ostream & (*man)(std::ostream &)){
  logStream << man;
  return *this;
}

Log & Log::operator<<(std::ios_base & (*man)(std::ios_base &)){
  logStream << man;
  return *this;
}

Log & Log::operator<<(Log & (*man)(Log &)){
  man(*this);
  return *this;
}

// Manipulator functions.
Log & lock(Log & log){
  log.guard.lock();
  return log;
}

Log & unlock(Log & log){
  log.guard.unlock();
  return log;
}

It works for me on Ubuntu 12.04 g++, compiled with:

g++ LogThreadTest.cpp -o log -std=c++0x -lpthread

The bits relevant to making custom manipulators was shamelessly cribbed from here but don't blame them for my incompetent copypasta.

Was it helpful?

Solution

It's a bad idea. Imagine this:

void foo()
{
    throw std::exception();
}

log << lock << "Write" << foo() << " I" << " want" << std::endl << unlock;
                          ^
                          exception!

This leaves your Log locked. Which is bad as other threads might be waiting to lock. This also happens everytime you simply forget to do the unlock. You should use RAII here:

// just providing a scope
{
    std::lock_guard<Log> lock(log);
    log << "Write" << foo() << " I" << " want" << std::endl;
}

You'd need to adjust your lock and unlock methods to have the signatures void lock() and void unlock() and make them member functions of the class Log.


On the other hand, that's rather bulky. Note that in C++11, using std::cout is thread-safe. So you can easily do

std::stringstream stream;
stream << "Write" << foo() << " I" << " want" << std::endl;
std::cout << stream.str();

which is completely free of additional locks.

OTHER TIPS

You don't need to pass the lock manipulator explicitly, you can use a sentry (with RAII semantics, as Hans Passant says)

class Log{
public:
  Log(std::ostream & os);
  ~Log();

  class Sentry {
      Log &log_;
  public:
      Sentry(Log &l) log_(l) { log_.lock(); }
      ~Sentry() { log_.unlock(); }

      // Input Functions just forward to log_.logStream
      Sentry& operator<<(const std::string & msg);
      Sentry& operator<<(const int & msg);
      Sentry& operator<<(std::ostream & (*man)(std::ostream &)); // Handles manipulators like endl.
      Sentry& operator<<(std::ios_base & (*man)(std::ios_base &)); // Handles manipulators like hex.
    };

    template <typename T>
    Sentry operator<<(T t) { return Sentry(*this) << t; }
    void lock();
    void unlock();

private:
  std::fstream logFile;
  std::ostream & logStream;
  std::mutex guard;
};

Now, writing

Log::log << "Write" << " what" << " I" << " want" << foo() << std::endl;

will:

  1. create a temporary Sentry object
    • which locks the Log object
  2. ... forwards each operator<< call to the parent Log instance ...
  3. and then goes out of scope at the end of the expression (or if foo throws)
    • which unlocks the Log object

Although this is safe, it also creates a lot of contention (that mutex is locked longer than I'd usually like, while formatting a message). A lower-contention approach would be to do the formatting into local storage (either thread-local or scope-local) with no locking at all, and then hold a lock just long enough to move that into a shared logging queue.

It's not really a very good idea, since someone will fatally forget the unlock at some point, causing all of the threads to hang at the next log. There's also the issue of what happens if one of the expressions you're logging throws. (It shouldn't happen, since you don't want to have actual behavior in the log statement, and things that don't have any behavior shouldn't throw. But you never know.)

The usual solution for logging is to use a special temporary object, which grabs the lock in its constructor, and frees it in the destructor (and also does a flush, and ensures that there is a trailing '\n'). This can be done very elegantly in C++11, using move semantics (because you generally want to create the instance of the temporary in a function, but the temporary whose destructor should act is outside the function); in C++03, you need to allow copying, and ensure that it is only the final copy which releases the lock.

Roughly speaking, your Log class would look something like:

struct LogData
{
    std::unique_lock<std::mutex> myLock
    std::ostream myStream;

    LogData( std::unique_lock<std::mutex>&& lock,
             std::streambuf* logStream )
        :  myLock( std::move( lock ) )
        ,  myStream( logStream )
    {
    }

    ~LogData()
    {
        myStream.flush();
    }
};

class Log
{
    LogData* myDest;
public:
    Log( LogData* dest )
        : myDest( dest )
    {
    }
    Log( Log&& other )
        : myDest( other.myDest )
    {
        other.myDest = nullptr;
    }
    ~Log()
    {
        if ( myDest ) {
            delete myDest;
        }
    }
    Log& operator=( Log const& other ) = delete;

    template <typename T>
    Log& operator<<( T const& obj )
    {
        if ( myDest != nullptr ) {
            myDest->myStream << obj;
        }
    }
};

(If your compiler doesn't have move semantics, you'll have to fake it somehow. If worst comes to worst, you can just make the single pointer member of Log mutable, and put the same code in a copy constructor with the traditional signature. Ugly, but as a work-around...)

In this solution, you would have a function log, which returns an instance of this class, with either a valid LogData (allocated dynamically), or a null pointer, depending on whether logging is active or not. (It's possible to avoid the dynamic allocation, by using a static instance of a LogData which has functions to start a log record, and to end it, but it is a little bit more complicated.)

Licensed under: CC-BY-SA with attribution
Not affiliated with StackOverflow
scroll top