core: use Boost.Log for logging

This makes the logging backend asynchronous

Change-Id: Ib3417e2ae424c5ae7237c071dc4698ca9769a33c
Refs: #2513
diff --git a/core/logger-factory.cpp b/core/logger-factory.cpp
index a463b94..aae7795 100644
--- a/core/logger-factory.cpp
+++ b/core/logger-factory.cpp
@@ -1,6 +1,6 @@
 /* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */
 /**
- * Copyright (c) 2014-2015,  Regents of the University of California,
+ * Copyright (c) 2014-2016,  Regents of the University of California,
  *                           Arizona Board of Regents,
  *                           Colorado State University,
  *                           University Pierre & Marie Curie, Sorbonne University,
@@ -26,6 +26,8 @@
 #include "logger-factory.hpp"
 
 #include <boost/range/adaptor/map.hpp>
+#include <boost/log/core.hpp>
+#include <boost/log/expressions.hpp>
 
 #ifdef HAVE_CUSTOM_LOGGER
 #error "This file should not be compiled when custom logger is used"
@@ -53,6 +55,21 @@
   m_levelNames["DEBUG"] = LOG_DEBUG;
   m_levelNames["TRACE"] = LOG_TRACE;
   m_levelNames["ALL"] = LOG_ALL;
+
+  auto backend = boost::make_shared<boost::log::sinks::text_ostream_backend>();
+  backend->auto_flush(true);
+  backend->add_stream(boost::shared_ptr<std::ostream>(&std::clog, bind([]{})));
+
+  m_sink = boost::make_shared<Sink>(backend);
+  m_sink->set_formatter(boost::log::expressions::stream << boost::log::expressions::message);
+  boost::log::core::get()->add_sink(m_sink);
+}
+
+LoggerFactory::~LoggerFactory()
+{
+  boost::log::core::get()->remove_sink(m_sink);
+  m_sink->stop();
+  m_sink->flush();
 }
 
 void
@@ -173,6 +190,12 @@
   }
 }
 
+void
+LoggerFactory::flushBackend()
+{
+  m_sink->flush();
+}
+
 Logger&
 LoggerFactory::create(const std::string& moduleName)
 {
diff --git a/core/logger-factory.hpp b/core/logger-factory.hpp
index 606ac1c..e61d60f 100644
--- a/core/logger-factory.hpp
+++ b/core/logger-factory.hpp
@@ -1,6 +1,6 @@
 /* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */
 /**
- * Copyright (c) 2014-2015,  Regents of the University of California,
+ * Copyright (c) 2014-2016,  Regents of the University of California,
  *                           Arizona Board of Regents,
  *                           Colorado State University,
  *                           University Pierre & Marie Curie, Sorbonne University,
@@ -35,6 +35,9 @@
 #include "config-file.hpp"
 #include "logger.hpp"
 
+#include <boost/log/sinks.hpp>
+#include <mutex>
+
 namespace nfd {
 
 class LoggerFactory : noncopyable
@@ -77,10 +80,15 @@
   void
   setDefaultLevel(LogLevel level);
 
+  void
+  flushBackend();
+
 private:
 
   LoggerFactory();
 
+  ~LoggerFactory();
+
   Logger&
   createLogger(const std::string& moduleName);
 
@@ -104,6 +112,9 @@
   mutable std::mutex m_loggersGuard;
 
   LogLevel m_defaultLevel;
+
+  typedef boost::log::sinks::asynchronous_sink<boost::log::sinks::text_ostream_backend> Sink;
+  boost::shared_ptr<Sink> m_sink;
 };
 
 inline LogLevel
diff --git a/core/logger.cpp b/core/logger.cpp
index 3a9da61..7803dfc 100644
--- a/core/logger.cpp
+++ b/core/logger.cpp
@@ -1,6 +1,6 @@
 /* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */
 /**
- * Copyright (c) 2014-2015,  Regents of the University of California,
+ * Copyright (c) 2014-2016,  Regents of the University of California,
  *                           Arizona Board of Regents,
  *                           Colorado State University,
  *                           University Pierre & Marie Curie, Sorbonne University,
@@ -36,25 +36,23 @@
 
 namespace nfd {
 
-std::mutex g_logMutex;
-
 Logger::Logger(const std::string& name, LogLevel level)
   : m_moduleName(name)
   , m_enabledLogLevel(level)
 {
 }
 
-const char*
-Logger::now()
+std::ostream&
+operator<<(std::ostream& os, const LoggerTimestamp&)
 {
   using namespace ndn::time;
 
   static const microseconds::rep ONE_SECOND = 1000000;
   microseconds::rep microsecondsSinceEpoch = duration_cast<microseconds>(
-                                             system_clock::now().time_since_epoch()).count();
+    system_clock::now().time_since_epoch()).count();
 
   // 10 (whole seconds) + '.' + 6 (fraction) + '\0'
-  static char buffer[10 + 1 + 6 + 1];
+  char buffer[10 + 1 + 6 + 1];
   BOOST_ASSERT_MSG(microsecondsSinceEpoch / ONE_SECOND <= 9999999999L,
                    "whole seconds cannot fit in 10 characters");
 
@@ -66,9 +64,7 @@
            microsecondsSinceEpoch / ONE_SECOND,
            microsecondsSinceEpoch % ONE_SECOND);
 
-  // It's okay to return a statically allocated buffer, because Logger::now() is invoked
-  // only once per log macro.
-  return buffer;
+  return os << buffer;
 }
 
 } // namespace nfd
diff --git a/core/logger.hpp b/core/logger.hpp
index 54af7cb..853a922 100644
--- a/core/logger.hpp
+++ b/core/logger.hpp
@@ -1,6 +1,6 @@
 /* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */
 /**
- * Copyright (c) 2014-2015,  Regents of the University of California,
+ * Copyright (c) 2014-2016,  Regents of the University of California,
  *                           Arizona Board of Regents,
  *                           Colorado State University,
  *                           University Pierre & Marie Curie, Sorbonne University,
@@ -31,8 +31,8 @@
 #ifdef HAVE_CUSTOM_LOGGER
 #include "custom-logger.hpp"
 #else
-
-#include <mutex>
+#include <boost/log/common.hpp>
+#include <boost/log/sources/logger.hpp>
 
 namespace nfd {
 
@@ -84,12 +84,8 @@
     m_moduleName = name;
   }
 
-  /** \return string representation of time since epoch: seconds.microseconds
-   *  \warning Return value is in a statically allocated buffer,
-   *           which subsequent calls will overwrite.
-   */
-  static const char*
-  now();
+public:
+  boost::log::sources::logger boostLogger;
 
 private:
   std::string m_moduleName;
@@ -103,6 +99,20 @@
   return output;
 }
 
+/**
+ * \brief a tag that writes a timestamp upon stream output
+ */
+struct LoggerTimestamp
+{
+};
+
+/**
+ * \brief write a timestamp to \p os
+ * \note This function is thread-safe.
+ */
+std::ostream&
+operator<<(std::ostream& os, const LoggerTimestamp&);
+
 } // namespace nfd
 
 #include "core/logger-factory.hpp"
@@ -130,16 +140,15 @@
 template<>                                                                 \
 nfd::Logger& cls<s1, s2>::g_logger = nfd::LoggerFactory::create(name)
 
-extern std::mutex g_logMutex;
+#define NFD_LOG_LINE(msg, expression) \
+LoggerTimestamp{} << " "#msg": " << "[" << g_logger  << "] " << expression
 
-#define NFD_LOG(level, msg, expression)                          \
-do {                                                             \
-  if (g_logger.isEnabled(::nfd::LOG_##level)) {                  \
-    std::lock_guard<std::mutex> lock(::nfd::g_logMutex);         \
-    std::clog << ::nfd::Logger::now() << " "#msg": "             \
-              << "[" << g_logger << "] " << expression << "\n";  \
-  }                                                              \
-} while (false)
+#define NFD_LOG(level, msg, expression)                                 \
+  do {                                                                  \
+    if (g_logger.isEnabled(::nfd::LOG_##level)) {                       \
+      BOOST_LOG(g_logger.boostLogger) << NFD_LOG_LINE(msg, expression); \
+    }                                                                   \
+  } while (false)
 
 #define NFD_LOG_TRACE(expression) NFD_LOG(TRACE, TRACE,   expression)
 #define NFD_LOG_DEBUG(expression) NFD_LOG(DEBUG, DEBUG,   expression)