core: prepend seconds.microseconds since epoch to logging messages

refs: #1440

Change-Id: I4ed478e574cf4eff68c3e80b3db1a6dbaab54089
diff --git a/daemon/core/logger.hpp b/daemon/core/logger.hpp
index 604c304..e0241ff 100644
--- a/daemon/core/logger.hpp
+++ b/daemon/core/logger.hpp
@@ -10,6 +10,10 @@
 #define NFD_CORE_LOGGER_HPP
 
 #include "common.hpp"
+#include <ndn-cpp-dev/util/time.hpp>
+
+/// \todo use when we enable C++11 (see todo in now())
+// #include <cinttypes>
 
 namespace nfd {
 
@@ -61,15 +65,42 @@
     m_moduleName = name;
   }
 
+
+  /// \brief return a string representation of time since epoch: seconds.microseconds
+  static std::string
+  now()
+  {
+    using namespace ndn::time;
+
+    static const microseconds::rep ONE_SECOND = 1000000;
+
+    // 10 (whole seconds) + '.' + 6 (fraction) + 1 (\0)
+    char buffer[10 + 1 + 6 + 1];
+
+    microseconds::rep microseconds_since_epoch =
+      duration_cast<microseconds>(system_clock::now().time_since_epoch()).count();
+
+    ::snprintf(buffer, sizeof(buffer), "%lld.%06lld",
+               static_cast<long long int>(microseconds_since_epoch / ONE_SECOND),
+               static_cast<long long int>(microseconds_since_epoch % ONE_SECOND));
+
+    /// \todo use this version when we enable C++11 to avoid casting
+    // ::snprintf(buffer, sizeof(buffer), "%" PRIdLEAST64 ".%06" PRIdLEAST64,
+    //            microseconds_since_epoch / ONE_SECOND,
+    //            microseconds_since_epoch % ONE_SECOND);
+
+    return std::string(buffer);
+  }
+
 private:
   std::string m_moduleName;
   LogLevel    m_enabledLogLevel;
 };
 
 inline std::ostream&
-operator<<(std::ostream& output, const Logger& obj)
+operator<<(std::ostream& output, const Logger& logger)
 {
-  output << obj.getName();
+  output << logger.getName();
   return output;
 }
 
@@ -79,21 +110,21 @@
 
 namespace nfd {
 
-#define NFD_LOG_INIT(name) \
+#define NFD_LOG_INIT(name)                                              \
 static nfd::Logger& g_logger = nfd::LoggerFactory::create(name);
 
-#define NFD_LOG_INCLASS_DECLARE()        \
+#define NFD_LOG_INCLASS_DECLARE()               \
 static nfd::Logger& g_logger;
 
-#define NFD_LOG_INCLASS_DEFINE(cls, name)        \
+#define NFD_LOG_INCLASS_DEFINE(cls, name)                       \
 nfd::Logger& cls::g_logger = nfd::LoggerFactory::create(name);
 
-#define NFD_LOG_INCLASS_TEMPLATE_DEFINE(cls, name)   \
+#define NFD_LOG_INCLASS_TEMPLATE_DEFINE(cls, name)                      \
 template<class T>                                                       \
 nfd::Logger& cls<T>::g_logger = nfd::LoggerFactory::create(name);
 
 #define NFD_LOG_INCLASS_TEMPLATE_SPECIALIZATION_DEFINE(cls, specialization, name) \
-template<> \
+template<>                                                              \
 nfd::Logger& cls<specialization>::g_logger = nfd::LoggerFactory::create(name);
 
 #define NFD_LOG_INCLASS_2TEMPLATE_SPECIALIZATION_DEFINE(cls, s1, s2, name) \
@@ -101,28 +132,31 @@
 nfd::Logger& cls<s1, s2>::g_logger = nfd::LoggerFactory::create(name);
 
 
-#define NFD_LOG_TRACE(expression) \
-if (g_logger.isEnabled(nfd::LOG_TRACE))                                 \
-  std::cerr<<"TRACE: "<<"["<<g_logger<<"] " << expression << "\n"
+#define NFD_LOG(level, expression)                                      \
+do {                                                                    \
+  if (g_logger.isEnabled(::nfd::LOG_##level))                           \
+    std::cerr << ::nfd::Logger::now() << " "#level": "                  \
+              << "[" << g_logger << "] " << expression << "\n";         \
+} while (false)
 
-#define NFD_LOG_DEBUG(expression)\
-if (g_logger.isEnabled(nfd::LOG_DEBUG))                                 \
-  std::cerr<<"DEBUG: "<<"["<<g_logger<<"] " << expression <<"\n"
+#define NFD_LOG_TRACE(expression) NFD_LOG(TRACE, expression)
+#define NFD_LOG_DEBUG(expression) NFD_LOG(DEBUG, expression)
+#define NFD_LOG_INFO(expression) NFD_LOG(INFO, expression)
+#define NFD_LOG_ERROR(expression) NFD_LOG(ERROR, expression)
 
+// specialize WARN because the message is "WARNING" instead of "WARN"
 #define NFD_LOG_WARN(expression)                                        \
-if (g_logger.isEnabled(nfd::LOG_WARN))                                  \
-  std::cerr<<"WARNING: "<<"["<<g_logger<<"] " << expression <<"\n"
+do {                                                                    \
+  if (g_logger.isEnabled(::nfd::LOG_WARN))                              \
+    std::cerr << ::nfd::Logger::now() << " WARNING: "                   \
+              << "[" << g_logger << "] " << expression << "\n";         \
+} while (false)
 
-#define NFD_LOG_INFO(expression)\
-if (g_logger.isEnabled(nfd::LOG_INFO))                          \
-  std::cerr<<"INFO: "<<"["<<g_logger<<"] " << expression <<"\n"
-
-#define NFD_LOG_ERROR(expression)                                       \
-if (g_logger.isEnabled(nfd::LOG_ERROR))                                  \
-  std::cerr<<"ERROR: "<<"["<<g_logger<<"] " << expression <<"\n"
-
-#define NFD_LOG_FATAL(expression)\
-std::cerr<<"FATAL: "<<"["<<g_logger<<"] " << expression <<"\n"
+#define NFD_LOG_FATAL(expression)                                       \
+do {                                                                    \
+  std::cerr << ::nfd::Logger::now() << " FATAL: "                       \
+            << "[" << g_logger << "] " << expression << "\n";           \
+} while (false)
 
 } //namespace nfd