Synchronize writing to log in a multi-threading process

Question

I implemented a Logger, so it can be used like ostream. e.g, if someone wants to write to the log - he can do something like this:

LOG << "hello world " << 6 << 8.6 << "\n";

The log will be written to the screen, to log file, and to any other source the user like to (this isn't the issue).

To achieve this goal, I created a macro for LOG:

#define LOG Logger::GetInstance()(__FILENAME__, __func__, __LINE__)

and overloaded operator () and operator <<:

template <typename T>
inline Logger& operator << (const T& msg) {
    std::stringstream ss;
    ss << msg;
    PrintToFile(ss.str());
    PrintToScreen(ss.str());
    return *this;
}

Logger& Logger::operator () (const std::string& sourceFile, const std::string& funcName, int lineNumber) {
    std::stringstream ss;
    ss << Utilities::GetFormattedTime("%d.%m.%y %H:%M:%S") << "::" << sourceFile << "(" << lineNumber << ")::" <<
            funcName << "::";
    PrintToFile(level, ss.str());
    PrintToScreen(level, ss.str());
    return *this;
}

The problem is when I have more than one thread that is running over my process, the print may be cut, because of context switch between the threads in the middle of the example line above (LOG << "hello world... ")

Using a mutex may not help, because operator << and operator () are not the same function.

Is there any brilliant or simple solution for this problem?

Answer 1

Just from top of my head. If you want to keep your approach with stream io operators as is, you can use sort of proxy object that locks\unlocks mutex.

Please, don't draw attention to coding style (especially swfull and dangerous Logger implementation). Below you can find brief illustration of mentioned idea.

template<class TLogger, class TLockObject>
class LoggerProxy
{
public:
    LoggerProxy(TLogger &logger, TLockObject &lockObj)
        : m_logger(logger),
        m_lockGuard(lockObj)
    {
    }

    template <typename T>
    inline LoggerProxy& operator << (const T& msg)
    {
        m_logger.Write(msg);
        return *this;
    }

private:
    TLogger & m_logger;
    std::lock_guard<typename TLockObject> m_lockGuard;
};

//Purpose of code below is just an illustration of usage LoggerProxy class. Don't use it in production code.
class Logger
{
public:
    static Logger& GetInstance()
    {
        static Logger instance;
        return instance;
    }
    static std::mutex& GetLockObject()
    {
        static std::mutex lockObj;
        return lockObj;
    }

    template <typename T>
    inline void Write (const T& msg) {
        std::cout << msg << std::endl;
    }
};

#define LOG LoggerProxy<Logger, std::mutex>(Logger::GetInstance(), Logger::GetLockObject())

int main()
{

    LOG << 10 << "HELLO" << 1.1;
    LOG << 101 << "HELLO2" << 11.1;

    return 0;
}

Answer 2

Use a std::mutex and lock on first use of operator() or operator<<. Then unlock if user string ends with \n. I assume you are sure that user finishes every log entry with linebreak.

class Logger {
     std::mutex mux;
     //...
   public:
     Logger& operator()(/*...*/) {
       mux.lock();
       // write to log
     }
     Logger& operator<<(const string& str) {
       // write to log
       if(str[str.size()-1] == '\n')
         mux.unlock();
     }
     //...
   }; 

Answer 3

You are right that operator<< and operator () are two different function, but that doesn't mean you cannot use a mutex.
From what i can gather from your example in both operator<< and operator() you call at the end the same two functions PrintToFile and PrintToScreen. This makes me think that the stream common to all threads is in these two functions and not in your operator<< and operator(), so you can actually lock a mutex inside those functions and have thread safe access to the logger. That being said it remains only to decide if you need two mutex or only one, that depends if you want the logging to be "atomic" as operation or you want to split it.
In the "atomic" version you should use a single version that holds a single mutex while writting to both screen and file thus your logs will execute sequentually.
Instead if you the splitted version you want to have two different functions with two different mutexes, one for the file logging and one for the screen loggin, this one a thread that wants to write to the file doesn't have to wait for threads that have already written to the file and are now writting to the screen. As always remember that having two mutexes has cost.

Answer 4

The first feeling is, that operator() and operator<< are unrelated. For that it feels better to use two mutex, one in PrintToFile and one in PrintToScreen.

But you also can use the same mutex to log both of your operator methods. As the first operator is a template function, we have not two but n functions. Each template instance is an additional one. So using a single mutex for all the functions did exactly what you want.

If your Logger is a class and the operators are members, you simply make your mutex a member variable which can be (un-)locked in each of your methods.

Answer 5

Share less, lock less.

If you're gonna synchronize on each operator<< you're going to have very lousy performance when your application is compiled with logging enabled.

This is a sketch of how I'd do it:

The Concept

namespace Logging {

    struct SinkConcept { void commit(std::string const&); }; // documentation only

Let's design a narrow contract where any logging sink has just that one method.

Now, let's create a LogTx - representing a log-transaction.

LogTx should be a move-aware temporary object creates a log message locally. This means that the buffers are not shared and need not be synchronized until you commit.

Commit is done from the destructor:

// movable log transaction (using arbitrary sink)
template <typename Sink> struct LogTx {
    LogTx(Sink& s) : _sink(s) {}
    LogTx(LogTx&&) = default;

    unique_flag        _armed;
    std::ostringstream _oss;
    Sink& _sink;

    ~LogTx() { if (_armed) _sink.commit(_oss.str()); }

    template <typename T> LogTx& operator<<(T&& rhs)&  { return (_oss << rhs), *this; }
    template <typename T> LogTx  operator<<(T&& rhs)&& { return (_oss << rhs), std::move(*this); }
};

That's all. The _armed flag makes sure the destructor doesn't commit in moved-from instances.

Some Sample Sinks

Now, let's add simple sinks so we can make a demo. Let's start with the simplest:

struct NullSink { void commit(std::string const&) const {} };

Now, let's get more useful. A sink to commit log transactions to any ostream object or reference:

template <typename Impl, bool Flush = true>
struct StreamSink {
    StreamSink(Impl stream_or_ref = {}) : _sor(std::move(stream_or_ref)) {}
    StreamSink(StreamSink&& rhs) : StreamSink(std::move(rhs._sor)) {}

    void commit(std::string const& msg) {
        std::lock_guard<std::mutex> lk(_mx);
        get() << msg << "\n";
        if (Flush) get() << std::flush;
    }

    std::ostream& get() { return _sor; }
  private:
    mutable std::mutex _mx;
    Impl _sor; // stream convertible to ostream&
};

And, because you were writing to several destinations in your example:

template <typename A, typename B> struct TeeSink { // dispatch to two sinks
    A a; B b;
    void commit(std::string const& msg) { a.commit(msg); b.commit(msg); }
};

Some Convenience Functions

Unless you use C++17, some factory functions will be welcome.

// factory functions (mostly not needed in c++17 with deduction guides)
template <typename A, typename B> 
TeeSink<A, B> tee(A&& a, B&& b) { return { std::forward<A>(a), std::forward<B>(b) }; }

StreamSink<std::ofstream, false> log_to(std::ofstream&& file) { return {std::move(file)}; }
StreamSink<std::reference_wrapper<std::ostream>, true> log_to(std::ostream& os) { return {os}; }

Let's also add global instances of sinks for standard streams, so that you can use these to get the same synchronization everywhere:

auto& log_to_stderr() {
    static StreamSink<std::reference_wrapper<std::ostream>, true> s_instance { log_to(std::cerr) };
    return s_instance;
}
auto& log_to_stdout() {
    static StreamSink<std::reference_wrapper<std::ostream>, true> s_instance { log_to(std::cout) };
    return s_instance;
}
auto& null_sink() {
    static NullSink const s_instance{};
    return s_instance;
}

template <typename Sink>
LogTx<Sink> make_tx(Sink& sink) { return {sink}; }

Finally the pièce de resistance: makeTx to create a LogTx for a given sink:

template <typename Sink>
LogTx<Sink> make_tx(Sink& sink) { return {sink}; }

DEMO TIME

Now we can put it together:

#define LOG_TO(sink) (Logging::make_tx(sink) << __FILE__ << ":" << __LINE__ << "\t" << __func__ << "\t")
#ifdef NOLOGGING
    #define LOG LOG_TO(Logging::null_sink())
#else
    static auto _file_sink = Logging::log_to(std::ofstream("demo.log"));
    static auto _both_sink = tee(_file_sink, Logging::log_to_stderr());
    #define LOG LOG_TO(_both_sink)
#endif

This is pretty much what you wanted:

Live On Coliru

#include <thread>
void worker(std::string id) {
    while (auto r = rand()%10) {
        std::this_thread::sleep_for(std::chrono::milliseconds(r));
        LOG << "Ping from " << id;
    }
}

int main() {
    LOG << "Hello";
    {
        std::thread a(worker, "A"), b(worker, "B");
        a.join();
        b.join();
    }
    LOG << "Bye";
}

Prints, to both stderr and demo.log:

main.cpp:104    main    Hello
main.cpp:99 worker  Ping from A
main.cpp:99 worker  Ping from B
main.cpp:99 worker  Ping from A
main.cpp:99 worker  Ping from B
main.cpp:99 worker  Ping from A
main.cpp:99 worker  Ping from B
main.cpp:99 worker  Ping from B
main.cpp:99 worker  Ping from A
main.cpp:99 worker  Ping from A
main.cpp:99 worker  Ping from A
main.cpp:99 worker  Ping from B
main.cpp:99 worker  Ping from A
main.cpp:99 worker  Ping from A
main.cpp:99 worker  Ping from A
main.cpp:99 worker  Ping from A
main.cpp:110    main    Bye

C++11 Full Listing

Added a c++11-compatible version, of which I include the full listing as to protect against link rot:

[C++11 Live On Coliru][http://coliru.stacked-crooked.com/a/6360aad26b037df2)

#include <functional> // for std::reference_wrapper
#include <iostream>
#include <sstream>
#include <fstream>
#include <mutex>

namespace Logging {

    // utility to safely implement movable log transactions
    struct unique_flag {
        bool value = true;
        unique_flag() = default;
        unique_flag(unique_flag&& rhs) : value(rhs.value) { rhs.value = false; }
        operator bool() const { return value; }
    };

    struct SinkConcept { void commit(std::string const&); }; // documentation only

    // movable log transaction (using arbitrary sink)
    template <typename Sink> struct LogTx {
        LogTx(Sink& s) : _sink(s) {}
        LogTx(LogTx&&) = default;

        unique_flag        _armed;
        std::ostringstream _oss;
        Sink& _sink;

        ~LogTx() { if (_armed) _sink.commit(_oss.str()); }

        template <typename T> LogTx& operator<<(T&& rhs)&  { return (_oss << rhs), *this; }
        template <typename T> LogTx  operator<<(T&& rhs)&& { return (_oss << rhs), std::move(*this); }
    };

    // Some sink models
    struct NullSink { void commit(std::string const&) const {} };

    template <typename Impl, bool Flush = true>
    struct StreamSink {
        StreamSink(Impl stream_or_ref = {}) : _sor(std::move(stream_or_ref)) {}
        StreamSink(StreamSink&& rhs) : StreamSink(std::move(rhs._sor)) {}

        void commit(std::string const& msg) {
            std::lock_guard<std::mutex> lk(_mx);
            get() << std::move(msg);
            if (Flush) 
                get() << std::endl;
            else
                get() << "\n";
        }

        std::ostream& get() { return _sor; }
      private:
        mutable std::mutex _mx;
        Impl _sor; // stream convertible to ostream&
    };

    template <typename A, typename B> struct TeeSink { // dispatch to two sinks
        A a; B b;
        void commit(std::string const& msg) { a.commit(msg); b.commit(msg); }
    };

    // factory functions (mostly not needed in c++17 with deduction guides)
    template <typename A, typename B> 
    TeeSink<A, B> tee(A&& a, B&& b) { return { std::forward<A>(a), std::forward<B>(b) }; }

    StreamSink<std::ofstream, false> log_to(std::ofstream&& file) { return {std::move(file)}; }
    StreamSink<std::reference_wrapper<std::ostream>, true> log_to(std::ostream& os) { return {os}; }

    StreamSink<std::reference_wrapper<std::ostream>, true>& log_to_stderr() {
        static StreamSink<std::reference_wrapper<std::ostream>, true> s_instance { log_to(std::cerr) };
        return s_instance;
    }
    StreamSink<std::reference_wrapper<std::ostream>, true>& log_to_stdout() {
        static StreamSink<std::reference_wrapper<std::ostream>, true> s_instance { log_to(std::cout) };
        return s_instance;
    }
    NullSink const& null_sink() {
        static NullSink const s_instance{};
        return s_instance;
    }

    template <typename Sink>
    LogTx<Sink> make_tx(Sink& sink) { return {sink}; }
}

#define LOG_TO(sink) (Logging::make_tx(sink) << __FILE__ << ":" << __LINE__ << "\t" << __func__ << "\t")
#ifdef NOLOGGING
    #define LOG      LOG_TO(Logging::null_sink())
#else
    static auto _file_sink = Logging::log_to(std::ofstream("demo.log"));
    static auto _both_sink = tee(_file_sink, Logging::log_to_stderr());
    #define LOG      LOG_TO(_both_sink)
#endif

#include <thread>
void worker(std::string id) {
    while (auto r = rand()%10) {
        std::this_thread::sleep_for(std::chrono::milliseconds(r));
        LOG << "Ping from " << id;
    }
}

int main() {
    LOG << "Hello";
    {
        std::thread a(worker, "A"), b(worker, "B");
        a.join();
        b.join();
    }
    LOG << "Bye";
}