Thread-safe logging singleton c++11

logging.hpp

#ifndef __LOGGING_HPP__
#define __LOGGING_HPP__

/*
Test this with something like:
g++ -std=c++11 -x c++ -pthread -DLOGGING_LEVEL_ALL -DTEST_LOGGING logging.hpp -o logging_test
./logging_test
*/

#include <string>
#include <stdexcept>
#include <iostream>
#include <fstream>
#include <sstream>
#include <mutex>
#include <unordered_map>
#include <memory>
#include <chrono>
#include <ctime>
#include <cstdlib>

namespace logging {

  //TODO: use macros (again) so __FILE__ __LINE__ could be automatically added to certain error levels?

  //the log levels we support
  enum class log_level : uint8_t { TRACE = 0, DEBUG = 1, INFO = 2, WARN = 3, ERROR = 4 };
  struct enum_hasher { template <typename T> std::size_t operator()(T t) const { return static_cast<std::size_t>(t); } };
  const std::unordered_map<log_level, std::string, enum_hasher> uncolored
    {
      {log_level::ERROR, " [ERROR] "}, {log_level::WARN, " [WARN] "}, {log_level::INFO, " [INFO] "},
      {log_level::DEBUG, " [DEBUG] "}, {log_level::TRACE, " [TRACE] "}
    };
  const std::unordered_map<log_level, std::string, enum_hasher> colored
    {
      {log_level::ERROR, " \x1b[31;1m[ERROR]\x1b[0m "}, {log_level::WARN, " \x1b[33;1m[WARN]\x1b[0m "},
      {log_level::INFO, " \x1b[32;1m[INFO]\x1b[0m "}, {log_level::DEBUG, " \x1b[34;1m[DEBUG]\x1b[0m "},
      {log_level::TRACE, " \x1b[37;1m[TRACE]\x1b[0m "}
    };

  //all, something in between, none or default to info
  #if defined(LOGGING_LEVEL_ALL) || defined(LOGGING_LEVEL_TRACE)
    constexpr log_level LOG_LEVEL_CUTOFF = log_level::TRACE;
  #elif defined(LOGGING_LEVEL_DEBUG)
    constexpr log_level LOG_LEVEL_CUTOFF = log_level::DEBUG;
  #elif defined(LOGGING_LEVEL_WARN)
    constexpr log_level LOG_LEVEL_CUTOFF = log_level::WARN;
  #elif defined(LOGGING_LEVEL_ERROR)
    constexpr log_level LOG_LEVEL_CUTOFF = log_level::ERROR;
  #elif defined(LOGGING_LEVEL_NONE)
    constexpr log_level LOG_LEVEL_CUTOFF = log_level::ERROR + 1;
  #else
    constexpr log_level LOG_LEVEL_CUTOFF = log_level::INFO;
  #endif

  //returns formated to: 'year/mo/dy hr:mn:sc.xxxxxx'
  inline std::string timestamp() {
    //get the time
    std::chrono::system_clock::time_point tp = std::chrono::system_clock::now();
    std::time_t tt = std::chrono::system_clock::to_time_t(tp);
    std::tm gmt{}; gmtime_r(&tt, &gmt);
    std::chrono::duration<double> fractional_seconds =
      (tp - std::chrono::system_clock::from_time_t(tt)) + std::chrono::seconds(gmt.tm_sec);
    //format the string
    std::string buffer("year/mo/dy hr:mn:sc.xxxxxx0");
    snprintf(&buffer.front(), buffer.length(), "%04d/%02d/%02d %02d:%02d:%09.6f",
             gmt.tm_year + 1900, gmt.tm_mon + 1, gmt.tm_mday, gmt.tm_hour, gmt.tm_min,
             fractional_seconds.count());
    //remove trailing null terminator added by snprintf
    buffer.pop_back();
    return buffer;
  }

  //logger base class, not pure virtual so you can use as a null logger if you want
  using logging_config_t = std::unordered_map<std::string, std::string>;
  class logger {
   public:
    logger() = delete;
    logger(const logging_config_t&) {};
    virtual ~logger() {};
    virtual void log(const std::string&, const log_level) {};
    virtual void log(const std::string&) {};
   protected:
    std::mutex lock;
  };

  //logger that writes to standard out
  class std_out_logger : public logger {
   public:
    std_out_logger() = delete;
    std_out_logger(const logging_config_t& config) : logger(config), levels(config.find("color") != config.end() ? colored : uncolored) {}
    virtual void log(const std::string& message, const log_level level) {
      if(level < LOG_LEVEL_CUTOFF)
        return;
      std::string output;
      output.reserve(message.length() + 64);
      output.append(timestamp());
      output.append(levels.find(level)->second);
      output.append(message);
      output.push_back('\n');
      log(output);
    }
    virtual void log(const std::string& message) {
      //cout is thread safe, to avoid multiple threads interleaving on one line
      //though, we make sure to only call the << operator once on std::cout
      //otherwise the << operators from different threads could interleave
      //obviously we dont care if flushes interleave
      //std::lock_guard<std::mutex> lk{lock};
      std::cout << message;
      std::cout.flush();
    }
   protected:
    const std::unordered_map<log_level, std::string, enum_hasher> levels;
  };

  //TODO: add log rolling
  //logger that writes to file
  class file_logger : public logger {
   public:
    file_logger() = delete;
    file_logger(const logging_config_t& config):logger(config) {
      //grab the file name
      auto name = config.find("file_name");
      if(name == config.end())
        throw std::runtime_error("No output file provided to file logger");
      file_name = name->second;

      //if we specify an interval
      reopen_interval = std::chrono::seconds(300);
      auto interval = config.find("reopen_interval");
      if(interval != config.end())
      {
        try {
          reopen_interval = std::chrono::seconds(std::stoul(interval->second));
        }
        catch(...) {
          throw std::runtime_error(interval->second + " is not a valid reopen interval");
        }
      }

      //crack the file open
      reopen();
    }
    virtual void log(const std::string& message, const log_level level) {
      if(level < LOG_LEVEL_CUTOFF)
        return;
      std::string output;
      output.reserve(message.length() + 64);
      output.append(timestamp());
      output.append(uncolored.find(level)->second);
      output.append(message);
      output.push_back('\n');
      log(output);
    }
    virtual void log(const std::string& message) {
      lock.lock();
      file << message;
      file.flush();
      lock.unlock();
      reopen();
    }
   protected:
    void reopen() {
      //TODO: use CLOCK_MONOTONIC_COARSE
      //check if it should be closed and reopened
      auto now = std::chrono::system_clock::now();
      lock.lock();
      if(now - last_reopen > reopen_interval) {
        last_reopen = now;
        try{ file.close(); }catch(...){}
        try {
          file.open(file_name, std::ofstream::out | std::ofstream::app);
          last_reopen = std::chrono::system_clock::now();
        }
        catch(std::exception& e) {
          try{ file.close(); }catch(...){}
          throw e;
        }
      }
      lock.unlock();
    }
    std::string file_name;
    std::ofstream file;
    std::chrono::seconds reopen_interval;
    std::chrono::system_clock::time_point last_reopen;
  };

  //a factory that can create loggers (that derive from 'logger') via function pointers
  //this way you could make your own logger that sends log messages to who knows where
  using logger_creator = logger *(*)(const logging_config_t&);
  class logger_factory {
   public:
    logger_factory() {
      creators.emplace("", [](const logging_config_t& config)->logger*{return new logger(config);});
      creators.emplace("std_out", [](const logging_config_t& config)->logger*{return new std_out_logger(config);});
      creators.emplace("file", [](const logging_config_t& config)->logger*{return new file_logger(config);});
    }
    logger* produce(const logging_config_t& config) const {
      //grab the type
      auto type = config.find("type");
      if(type == config.end())
        throw std::runtime_error("Logging factory configuration requires a type of logger");
      //grab the logger
      auto found = creators.find(type->second);
      if(found != creators.end())
        return found->second(config);
      //couldn't get a logger
      throw std::runtime_error("Couldn't produce logger for type: " + type->second);
    }
   protected:
    std::unordered_map<std::string, logger_creator> creators;
  };

  //statically get a factory
  inline logger_factory& get_factory() {
    static logger_factory factory_singleton{};
    return factory_singleton;
  }

  //get at the singleton
  inline logger& get_logger(const logging_config_t& config = { {"type", "std_out"}, {"color", ""} }) {
    static std::unique_ptr<logger> singleton(get_factory().produce(config));
    return *singleton;
  }

  //configure the singleton (once only)
  inline void configure(const logging_config_t& config) {
    get_logger(config);
  }

  //statically log manually without the macros below
  inline void log(const std::string& message, const log_level level) {
    get_logger().log(message, level);
  }

  //statically log manually without a level or maybe with a custom one
  inline void log(const std::string& message) {
    get_logger().log(message);
  }

  //these standout when reading code
  inline void TRACE(const std::string& message) {
    get_logger().log(message, log_level::TRACE);
  }
  inline void DEBUG(const std::string& message) {
    get_logger().log(message, log_level::DEBUG);
  }
  inline void INFO(const std::string& message) {
    get_logger().log(message, log_level::INFO);
  }
  inline void WARN(const std::string& message) {
    get_logger().log(message, log_level::WARN);
  }
  inline void ERROR(const std::string& message) {
    get_logger().log(message, log_level::ERROR);
  }
}

#endif //__LOGGING_HPP__

#ifdef TEST_LOGGING

#include <thread>
#include <vector>
#include <functional>
#include <memory>

void work() {
  std::ostringstream s; s << "hi my name is: " << std::this_thread::get_id();
  std::string id = s.str();
  for(size_t i  = 0; i < 10000; ++i) {
    logging::ERROR(id);
    logging::WARN(id);
    logging::INFO(id);
    logging::DEBUG(id);
    logging::TRACE(id);
  }
}

int main(void) {
  //configure logging, if you dont it defaults to standard out logging with colors
  //logging::configure({ {"type", "file"}, {"file_name", "test.log"}, {"reopen_interval", "1"} });
  
  //start up some threads
  std::vector<std::shared_ptr<std::thread>> threads(std::thread::hardware_concurrency());
  for(auto& thread : threads) {
    thread.reset(new std::thread(work));
  }

  //wait for finish
  for(auto& thread : threads) {
    thread->join();
  }
  
  return 0;
}

#endif

Hey kevinkreiser ! Your logger is amazing and excellent . I'm a newbie in multithreading coding and I have read your code to learn how to write thread-safe code. I'm a little confused by 2 parts of your code:

1st : in lines between 137 and 138 (it seems gist doesn't support line number reference)

      //crack the file open
reopen();

The reopen function is the most confusing part of the file_logger. Why do we need to reopen the log file in an interval of 300 seconds(the default setting)? I have googled it on StackOverflow but found nothing helpful. Is it related to some system restriction ?(I don't know).

2nd: there is code like

lock.lock();
file << message;
file.flush();
lock.unlock();

Is it better to use thestd::lock_guard<std::mutex> lk(lock) way rathen than manual locking and unlocking?

Finally, thanks for your logger 👍 💯

@BlurryLight thanks for the questions

1. we periodically close and reopen the file handle to make sure the contents of the file buffer are written to disk. implementation of fstream depends on the platform of course, but it is my undrestanding that the several implementations buffer output to memory and then only flush to the actual filesystem when they see a new line or after the internal memory buffer is full for example. this is a performance thing they do to avoid having to write every individual character to disk on every write. you should be able to google ofstream buffering for some more info about this. you're other question brings up an important point, though, notice that we have flush called manually in there. unless there is some other reason i am forgetting about why we re-obtain the file handle, it should be possible completely remove reopen since we are manually flushing on every log. this is probably an oversight on my part 😄

2. you could do it that way yes. using lock_guard is basically a way to use scope to control when a lock is obtained and then released. in the current implementation since locking essentially happens around the whole of the method (through reopen as well) then it would be a nice simplification to use a lock_guard

@kevinkreiser Looks good! What is the license for this code? Thank you!

@cxw42 i think that this one fits best, cheers!

This is free and unencumbered software released into the public domain.

Anyone is free to copy, modify, publish, use, compile, sell, or
distribute this software, either in source code form or as a compiled
binary, for any purpose, commercial or non-commercial, and by any
means.

In jurisdictions that recognize copyright laws, the author or authors
of this software dedicate any and all copyright interest in the
software to the public domain. We make this dedication for the benefit
of the public at large and to the detriment of our heirs and
successors. We intend this dedication to be an overt act of
relinquishment in perpetuity of all present and future rights to this
software under copyright law.

THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.
IN NO EVENT SHALL THE AUTHORS BE LIABLE FOR ANY CLAIM, DAMAGES OR
OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE,
ARISING FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR
OTHER DEALINGS IN THE SOFTWARE.

For more information, please refer to <https://unlicense.org>

@kevinkreiser Thanks for the quick response!

@kevinkreiser
Thanks for the great implementation!
Unfortunately, I couldn't have it compiled successfully on Windows - VS 2019
'gmtime_r': identifier not found'

@bone3011, @kevinkreiser
Many thanks from me too for the good implementation!
For my Windows Embarcadero enviroment I use gmtime_s() instead of gmtime_r().
This functionality is sufficient in my small project.
Regeards, Uwe

Many thanks for your work, which I gleefully forked here and modified to work with Windows.

Hey, Kevin!
My clang compiler doesn't like the usage of sprintf in line 65 ff. ;-)

I suggest:

std::string buffer;
int size = snprintf(NULL, 0, "%04d/%02d/%02d %02d:%02d:%09.6f", gmt.tm_year + 1900, gmt.tm_mon + 1,
gmt.tm_mday, gmt.tm_hour, gmt.tm_min, fractional_seconds.count());
buffer.reserve(size+1);
snprintf(&buffer.front(), size, "%04d/%02d/%02d %02d:%02d:%09.6f", gmt.tm_year + 1900, gmt.tm_mon + 1,
gmt.tm_mday, gmt.tm_hour, gmt.tm_min, fractional_seconds.count());

updated

@cduvenhorst yeah i made a couple changes over in valhalla for this but havent brought them back to the gist yet:

valhalla/valhalla@2a13dcd
valhalla/valhalla@d44cd26

@kevinkreiser Oops. Missed it! ;-) Thanks!

greate work

can I ask for one addition? Since the configuration is unordered_map we can only have one type of logger. Can we have at the same time a file and an std out logger? So that everything is saved on disk but at the same time have colours on screen

I tried something like

			logging::configure({ {"type", "file"}, {"file_name", log_file}, {"reopen_interval", "1"},
							     {"type", "std_out"}, {"color", "1"}
			});

but "type" is replaced and there can be only one

also the code below isn't valid (again due to unordered map

			logging::configure({ {{"type", "file"}, {"file_name", log_file}, {"reopen_interval", "1"}},
							     {{"type", "std_out"}, {"color", "1"}}
			});

@hamlatzis i think to support this properly we should expand the interface to take a vector of unordered_maps and then have the logger factory return a wrapper logger that simply iterates over the list of all the loggers that were configured. should be pretty straight forward