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
diff --git a/tests/core/logger.cpp b/tests/core/logger.cpp
index 0aa2e47..faff2a6 100644
--- a/tests/core/logger.cpp
+++ b/tests/core/logger.cpp
@@ -9,6 +9,8 @@
#include "core/logger.hpp"
#include <boost/test/unit_test.hpp>
+#include <boost/algorithm/string.hpp>
+#include <boost/algorithm/string/classification.hpp>
#include <iostream>
@@ -38,100 +40,252 @@
std::stringstream m_buffer;
std::streambuf* m_savedBuf;
LogLevel m_savedLevel;
+
};
BOOST_FIXTURE_TEST_CASE(Basic, LoggerFixture)
{
+ using namespace ndn::time;
+ using std::string;
+
+ const ndn::time::microseconds::rep ONE_SECOND = 1000000;
+
NFD_LOG_INIT("BasicTests");
g_logger.setLogLevel(LOG_ALL);
- NFD_LOG_TRACE("trace message JHGFDSR^1");
- NFD_LOG_DEBUG("debug message IGg2474fdksd fo " << 15 << 16 << 17);
- NFD_LOG_WARN("warning message XXXhdhd11" << 1 << "x");
- NFD_LOG_INFO("info message Jjxjshj13");
- NFD_LOG_ERROR("error message !#$&^%$#@");
- NFD_LOG_FATAL("fatal message JJSjaamcng");
+ const string EXPECTED[] =
+ {
+ "TRACE:", "[BasicTests]", "trace-message-JHGFDSR^1\n",
+ "DEBUG:", "[BasicTests]", "debug-message-IGg2474fdksd-fo-151617\n",
+ "WARNING:", "[BasicTests]", "warning-message-XXXhdhd111x\n",
+ "INFO:", "[BasicTests]", "info-message-Jjxjshj13\n",
+ "ERROR:", "[BasicTests]", "error-message-!#$&^%$#@\n",
+ "FATAL:", "[BasicTests]", "fatal-message-JJSjaamcng\n",
+ };
- BOOST_CHECK_EQUAL(m_buffer.str(),
- "TRACE: [BasicTests] trace message JHGFDSR^1\n"
- "DEBUG: [BasicTests] debug message IGg2474fdksd fo 151617\n"
- "WARNING: [BasicTests] warning message XXXhdhd111x\n"
- "INFO: [BasicTests] info message Jjxjshj13\n"
- "ERROR: [BasicTests] error message !#$&^%$#@\n"
- "FATAL: [BasicTests] fatal message JJSjaamcng\n"
- );
+ const size_t N_EXPECTED = sizeof(EXPECTED) / sizeof(string);
+
+ microseconds::rep before =
+ duration_cast<microseconds>(system_clock::now().time_since_epoch()).count();
+
+ NFD_LOG_TRACE("trace-message-JHGFDSR^1");
+ NFD_LOG_DEBUG("debug-message-IGg2474fdksd-fo-" << 15 << 16 << 17);
+ NFD_LOG_WARN("warning-message-XXXhdhd11" << 1 <<"x");
+ NFD_LOG_INFO("info-message-Jjxjshj13");
+ NFD_LOG_ERROR("error-message-!#$&^%$#@");
+ NFD_LOG_FATAL("fatal-message-JJSjaamcng");
+
+ microseconds::rep after =
+ duration_cast<microseconds>(system_clock::now().time_since_epoch()).count();
+
+ const string buffer = m_buffer.str();
+
+ std::vector<string> components;
+ boost::split(components, buffer, boost::is_any_of(" ,\n"));
+
+ // std::cout << components.size() << " for " << moduleName << std::endl;
+ // for (size_t i = 0; i < components.size(); ++i)
+ // {
+ // std::cout << "-> " << components[i] << std::endl;
+ // }
+
+ // expected + number of timestamps (one per log statement) + trailing newline of last statement
+ BOOST_REQUIRE_EQUAL(components.size(), N_EXPECTED + 6 + 1);
+
+ std::vector<std::string>::const_iterator componentIter = components.begin();
+ for (size_t i = 0; i < N_EXPECTED; ++i)
+ {
+ // timestamp LOG_LEVEL: [ModuleName] message\n
+
+ const string& timestamp = *componentIter;
+ // std::cout << "timestamp = " << timestamp << std::endl;
+ ++componentIter;
+
+ size_t timeDelimiterPosition = timestamp.find(".");
+
+ BOOST_REQUIRE_NE(string::npos, timeDelimiterPosition);
+
+ string secondsString = timestamp.substr(0, timeDelimiterPosition);
+ string usecondsString = timestamp.substr(timeDelimiterPosition + 1);
+
+ microseconds::rep extractedTime =
+ ONE_SECOND * boost::lexical_cast<microseconds::rep>(secondsString) +
+ boost::lexical_cast<microseconds::rep>(usecondsString);
+
+ // std::cout << "before=" << before << " extracted=" << extractedTime << " after=" << after << std::endl;
+
+ BOOST_REQUIRE(before <= extractedTime);
+ BOOST_REQUIRE(extractedTime <= after);
+
+ // LOG_LEVEL:
+ BOOST_REQUIRE_EQUAL(*componentIter, EXPECTED[i]);
+ ++componentIter;
+ ++i;
+
+ // [ModuleName]
+ BOOST_REQUIRE_EQUAL(*componentIter, EXPECTED[i]);
+ ++componentIter;
+ ++i;
+
+ const string& message = *componentIter;
+
+ // std::cout << "message = " << message << std::endl;
+
+ // add back the newline that we split on
+ BOOST_REQUIRE_EQUAL(message + "\n", EXPECTED[i]);
+ ++componentIter;
+ }
+
}
+
BOOST_FIXTURE_TEST_CASE(ConfigureFactory, LoggerFixture)
{
+ using namespace ndn::time;
+ using std::string;
+
+ const ndn::time::microseconds::rep ONE_SECOND = 1000000;
+
NFD_LOG_INIT("ConfigureFactoryTests");
- const std::string LOG_CONFIG =
+ const string LOG_CONFIG =
"log\n"
"{\n"
" default_level INFO\n"
"}\n";
+ LoggerFactory::getInstance().setDefaultLevel(LOG_ALL);
+
ConfigFile config;
LoggerFactory::getInstance().setConfigFile(config);
config.parse(LOG_CONFIG, false, "LOG_CONFIG");
- NFD_LOG_TRACE("trace message JHGFDSR^1");
- NFD_LOG_DEBUG("debug message IGg2474fdksd fo " << 15 << 16 << 17);
- NFD_LOG_WARN("warning message XXXhdhd11" << 1 << "x");
- NFD_LOG_INFO("info message Jjxjshj13");
- NFD_LOG_ERROR("error message !#$&^%$#@");
- NFD_LOG_FATAL("fatal message JJSjaamcng");
+ BOOST_REQUIRE_EQUAL(LoggerFactory::getInstance().getDefaultLevel(), LOG_INFO);
- BOOST_CHECK_EQUAL(m_buffer.str(),
- "WARNING: [ConfigureFactoryTests] warning message XXXhdhd111x\n"
- "INFO: [ConfigureFactoryTests] info message Jjxjshj13\n"
- "ERROR: [ConfigureFactoryTests] error message !#$&^%$#@\n"
- "FATAL: [ConfigureFactoryTests] fatal message JJSjaamcng\n"
- );
+ const std::string EXPECTED[] =
+ {
+ "WARNING:", "[ConfigureFactoryTests]", "warning-message-XXXhdhd111x\n",
+ "INFO:", "[ConfigureFactoryTests]", "info-message-Jjxjshj13\n",
+ "ERROR:", "[ConfigureFactoryTests]", "error-message-!#$&^%$#@\n",
+ "FATAL:", "[ConfigureFactoryTests]", "fatal-message-JJSjaamcng\n",
+ };
+
+ const size_t N_EXPECTED = sizeof(EXPECTED) / sizeof(std::string);
+
+ microseconds::rep before =
+ duration_cast<microseconds>(system_clock::now().time_since_epoch()).count();
+
+ NFD_LOG_TRACE("trace-message-JHGFDSR^1");
+ NFD_LOG_DEBUG("debug-message-IGg2474fdksd-fo-" << 15 << 16 << 17);
+ NFD_LOG_WARN("warning-message-XXXhdhd11" << 1 <<"x");
+ NFD_LOG_INFO("info-message-Jjxjshj13");
+ NFD_LOG_ERROR("error-message-!#$&^%$#@");
+ NFD_LOG_FATAL("fatal-message-JJSjaamcng");
+
+ microseconds::rep after =
+ duration_cast<microseconds>(system_clock::now().time_since_epoch()).count();
+
+ const string buffer = m_buffer.str();
+
+ std::vector<string> components;
+ boost::split(components, buffer, boost::is_any_of(" ,\n"));
+
+ // std::cout << components.size() << " for " << moduleName << std::endl;
+ // for (size_t i = 0; i < components.size(); ++i)
+ // {
+ // std::cout << "-> " << components[i] << std::endl;
+ // }
+
+ // expected + number of timestamps (one per log statement) + trailing newline of last statement
+ BOOST_REQUIRE_EQUAL(components.size(), N_EXPECTED + 4 + 1);
+
+ std::vector<std::string>::const_iterator componentIter = components.begin();
+ for (size_t i = 0; i < N_EXPECTED; ++i)
+ {
+ // timestamp LOG_LEVEL: [ModuleName] message\n
+
+ const string& timestamp = *componentIter;
+ // std::cout << "timestamp = " << timestamp << std::endl;
+ ++componentIter;
+
+ size_t timeDelimiterPosition = timestamp.find(".");
+
+ BOOST_REQUIRE_NE(string::npos, timeDelimiterPosition);
+
+ string secondsString = timestamp.substr(0, timeDelimiterPosition);
+ string usecondsString = timestamp.substr(timeDelimiterPosition + 1);
+
+ microseconds::rep extractedTime =
+ ONE_SECOND * boost::lexical_cast<microseconds::rep>(secondsString) +
+ boost::lexical_cast<microseconds::rep>(usecondsString);
+
+ // std::cout << "before=" << before << " extracted=" << extractedTime << " after=" << after << std::endl;
+
+ BOOST_REQUIRE(before <= extractedTime);
+ BOOST_REQUIRE(extractedTime <= after);
+
+ // LOG_LEVEL:
+ BOOST_REQUIRE_EQUAL(*componentIter, EXPECTED[i]);
+ ++componentIter;
+ ++i;
+
+ // [ModuleName]
+ BOOST_REQUIRE_EQUAL(*componentIter, EXPECTED[i]);
+ ++componentIter;
+ ++i;
+
+ const string& message = *componentIter;
+
+ // std::cout << "message = " << message << std::endl;
+
+ // add back the newline that we split on
+ BOOST_REQUIRE_EQUAL(message + "\n", EXPECTED[i]);
+ ++componentIter;
+ }
}
BOOST_FIXTURE_TEST_CASE(TestNumberLevel, LoggerFixture)
{
- NFD_LOG_INIT("TestNumberLevel");
-
const std::string LOG_CONFIG =
"log\n"
"{\n"
" default_level 2\n" // equivalent of WARN
"}\n";
+ LoggerFactory::getInstance().setDefaultLevel(LOG_ALL);
+
ConfigFile config;
LoggerFactory::getInstance().setConfigFile(config);
config.parse(LOG_CONFIG, false, "LOG_CONFIG");
- NFD_LOG_TRACE("trace message JHGFDSR^1");
- NFD_LOG_DEBUG("debug message IGg2474fdksd fo " << 15 << 16 << 17);
- NFD_LOG_WARN("warning message XXXhdhd11" << 1 << "x");
- NFD_LOG_INFO("info message Jjxjshj13");
- NFD_LOG_ERROR("error message !#$&^%$#@");
- NFD_LOG_FATAL("fatal message JJSjaamcng");
-
- BOOST_CHECK_EQUAL(m_buffer.str(),
- "WARNING: [TestNumberLevel] warning message XXXhdhd111x\n"
- "ERROR: [TestNumberLevel] error message !#$&^%$#@\n"
- "FATAL: [TestNumberLevel] fatal message JJSjaamcng\n"
- );
+ BOOST_REQUIRE_EQUAL(LoggerFactory::getInstance().getDefaultLevel(), LOG_WARN);
}
static void
testModuleBPrint()
{
NFD_LOG_INIT("TestModuleB");
- NFD_LOG_DEBUG("debug message IGg2474fdksd fo " << 15 << 16 << 17);
+ NFD_LOG_DEBUG("debug-message-IGg2474fdksd-fo-" << 15 << 16 << 17);
}
BOOST_FIXTURE_TEST_CASE(LimitModules, LoggerFixture)
{
+ using namespace ndn::time;
+ using std::string;
+
NFD_LOG_INIT("TestModuleA");
+ const ndn::time::microseconds::rep ONE_SECOND = 1000000;
+
+ const std::string EXPECTED[] =
+ {
+ "WARNING:", "[TestModuleA]", "warning-message-XXXhdhd111x\n",
+ };
+
+ const size_t N_EXPECTED = sizeof(EXPECTED) / sizeof(std::string);
+
const std::string LOG_CONFIG =
"log\n"
"{\n"
@@ -143,21 +297,80 @@
config.parse(LOG_CONFIG, false, "LOG_CONFIG");
- // this should print
- NFD_LOG_WARN("warning message XXXhdhd11" << 1 << "x");
+ microseconds::rep before =
+ duration_cast<microseconds>(system_clock::now().time_since_epoch()).count();
+
+ // this should print
+ NFD_LOG_WARN("warning-message-XXXhdhd11" << 1 << "x");
// this should not because it's level is < WARN
testModuleBPrint();
- BOOST_CHECK_EQUAL(m_buffer.str(),
- "WARNING: [TestModuleA] warning message XXXhdhd111x\n"
- );
+ microseconds::rep after =
+ duration_cast<microseconds>(system_clock::now().time_since_epoch()).count();
+
+ const string buffer = m_buffer.str();
+
+ std::vector<string> components;
+ boost::split(components, buffer, boost::is_any_of(" ,\n"));
+
+ // expected + number of timestamps (one per log statement) + trailing newline of last statement
+ BOOST_REQUIRE_EQUAL(components.size(), N_EXPECTED + 1 + 1);
+
+ std::vector<std::string>::const_iterator componentIter = components.begin();
+ for (size_t i = 0; i < N_EXPECTED; ++i)
+ {
+ // timestamp LOG_LEVEL: [ModuleName] message\n
+
+ const string& timestamp = *componentIter;
+ // std::cout << "timestamp = " << timestamp << std::endl;
+ ++componentIter;
+
+ size_t timeDelimiterPosition = timestamp.find(".");
+
+ BOOST_REQUIRE_NE(string::npos, timeDelimiterPosition);
+
+ string secondsString = timestamp.substr(0, timeDelimiterPosition);
+ string usecondsString = timestamp.substr(timeDelimiterPosition + 1);
+
+ microseconds::rep extractedTime =
+ ONE_SECOND * boost::lexical_cast<microseconds::rep>(secondsString) +
+ boost::lexical_cast<microseconds::rep>(usecondsString);
+
+ // std::cout << "before=" << before << " extracted=" << extractedTime << " after=" << after << std::endl;
+
+ BOOST_REQUIRE(before <= extractedTime);
+ BOOST_REQUIRE(extractedTime <= after);
+
+ // LOG_LEVEL:
+ BOOST_REQUIRE_EQUAL(*componentIter, EXPECTED[i]);
+ ++componentIter;
+ ++i;
+
+ // [ModuleName]
+ BOOST_REQUIRE_EQUAL(*componentIter, EXPECTED[i]);
+ ++componentIter;
+ ++i;
+
+ const string& message = *componentIter;
+
+ // std::cout << "message = " << message << std::endl;
+
+ // add back the newline that we split on
+ BOOST_REQUIRE_EQUAL(message + "\n", EXPECTED[i]);
+ ++componentIter;
+ }
}
BOOST_FIXTURE_TEST_CASE(ExplicitlySetModule, LoggerFixture)
{
+ using namespace ndn::time;
+ using std::string;
+
NFD_LOG_INIT("TestModuleA");
+ const ndn::time::microseconds::rep ONE_SECOND = 1000000;
+
const std::string LOG_CONFIG =
"log\n"
"{\n"
@@ -170,16 +383,82 @@
config.parse(LOG_CONFIG, false, "LOG_CONFIG");
+ microseconds::rep before =
+ duration_cast<microseconds>(system_clock::now().time_since_epoch()).count();
+
// this should print
- NFD_LOG_WARN("warning message XXXhdhd11" << 1 << "x");
+ NFD_LOG_WARN("warning-message-XXXhdhd11" << 1 << "x");
// this too because its level is explicitly set to DEBUG
testModuleBPrint();
- BOOST_CHECK_EQUAL(m_buffer.str(),
- "WARNING: [TestModuleA] warning message XXXhdhd111x\n"
- "DEBUG: [TestModuleB] debug message IGg2474fdksd fo 151617\n"
- );
+ microseconds::rep after =
+ duration_cast<microseconds>(system_clock::now().time_since_epoch()).count();
+
+ const std::string EXPECTED[] =
+ {
+ "WARNING:", "[TestModuleA]", "warning-message-XXXhdhd111x\n",
+ "DEBUG:", "[TestModuleB]", "debug-message-IGg2474fdksd-fo-151617\n",
+ };
+
+ const size_t N_EXPECTED = sizeof(EXPECTED) / sizeof(std::string);
+
+ const string buffer = m_buffer.str();
+
+ std::vector<string> components;
+ boost::split(components, buffer, boost::is_any_of(" ,\n"));
+
+ // for (size_t i = 0; i < components.size(); ++i)
+ // {
+ // std::cout << "-> " << components[i] << std::endl;
+ // }
+
+ // expected + number of timestamps (one per log statement) + trailing newline of last statement
+ BOOST_REQUIRE_EQUAL(components.size(), N_EXPECTED + 2 + 1);
+
+ std::vector<std::string>::const_iterator componentIter = components.begin();
+ for (size_t i = 0; i < N_EXPECTED; ++i)
+ {
+ // timestamp LOG_LEVEL: [ModuleName] message\n
+
+ const string& timestamp = *componentIter;
+ // std::cout << "timestamp = " << timestamp << std::endl;
+ ++componentIter;
+
+ size_t timeDelimiterPosition = timestamp.find(".");
+
+ BOOST_REQUIRE_NE(string::npos, timeDelimiterPosition);
+
+ string secondsString = timestamp.substr(0, timeDelimiterPosition);
+ string usecondsString = timestamp.substr(timeDelimiterPosition + 1);
+
+ microseconds::rep extractedTime =
+ ONE_SECOND * boost::lexical_cast<microseconds::rep>(secondsString) +
+ boost::lexical_cast<microseconds::rep>(usecondsString);
+
+ // std::cout << "before=" << before << " extracted=" << extractedTime << " after=" << after << std::endl;
+
+ BOOST_REQUIRE(before <= extractedTime);
+ BOOST_REQUIRE(extractedTime <= after);
+
+ // LOG_LEVEL:
+ BOOST_REQUIRE_EQUAL(*componentIter, EXPECTED[i]);
+ ++componentIter;
+ ++i;
+
+ // [ModuleName]
+ BOOST_REQUIRE_EQUAL(*componentIter, EXPECTED[i]);
+ ++componentIter;
+ ++i;
+
+ const string& message = *componentIter;
+
+ // std::cout << "message = " << message << std::endl;
+
+ // add back the newline that we split on
+ BOOST_REQUIRE_EQUAL(message + "\n", EXPECTED[i]);
+ ++componentIter;
+ }
}
static bool
@@ -236,12 +515,12 @@
void
writeLogs()
{
- NFD_LOG_TRACE("trace message JHGFDSR^1");
- NFD_LOG_DEBUG("debug message IGg2474fdksd fo " << 15 << 16 << 17);
- NFD_LOG_WARN("warning message XXXhdhd11" << 1 << "x");
- NFD_LOG_INFO("info message Jjxjshj13");
- NFD_LOG_ERROR("error message !#$&^%$#@");
- NFD_LOG_FATAL("fatal message JJSjaamcng");
+ NFD_LOG_TRACE("trace-message-JHGFDSR^1");
+ NFD_LOG_DEBUG("debug-message-IGg2474fdksd-fo-" << 15 << 16 << 17);
+ NFD_LOG_WARN("warning-message-XXXhdhd11" << 1 <<"x");
+ NFD_LOG_INFO("info-message-Jjxjshj13");
+ NFD_LOG_ERROR("error-message-!#$&^%$#@");
+ NFD_LOG_FATAL("fatal-message-JJSjaamcng");
}
private:
@@ -252,16 +531,82 @@
BOOST_FIXTURE_TEST_CASE(InClass, InClassLogger)
{
+ using namespace ndn::time;
+ using std::string;
+
+ const ndn::time::microseconds::rep ONE_SECOND = 1000000;
+
+ microseconds::rep before =
+ duration_cast<microseconds>(system_clock::now().time_since_epoch()).count();
+
writeLogs();
- BOOST_CHECK_EQUAL(m_buffer.str(),
- "TRACE: [InClassLogger] trace message JHGFDSR^1\n"
- "DEBUG: [InClassLogger] debug message IGg2474fdksd fo 151617\n"
- "WARNING: [InClassLogger] warning message XXXhdhd111x\n"
- "INFO: [InClassLogger] info message Jjxjshj13\n"
- "ERROR: [InClassLogger] error message !#$&^%$#@\n"
- "FATAL: [InClassLogger] fatal message JJSjaamcng\n"
- );
+ microseconds::rep after =
+ duration_cast<microseconds>(system_clock::now().time_since_epoch()).count();
+
+ const string EXPECTED[] =
+ {
+ "TRACE:", "[InClassLogger]", "trace-message-JHGFDSR^1\n",
+ "DEBUG:", "[InClassLogger]", "debug-message-IGg2474fdksd-fo-151617\n",
+ "WARNING:", "[InClassLogger]", "warning-message-XXXhdhd111x\n",
+ "INFO:", "[InClassLogger]", "info-message-Jjxjshj13\n",
+ "ERROR:", "[InClassLogger]", "error-message-!#$&^%$#@\n",
+ "FATAL:", "[InClassLogger]", "fatal-message-JJSjaamcng\n",
+ };
+
+ const size_t N_EXPECTED = sizeof(EXPECTED) / sizeof(string);
+
+ const string buffer = m_buffer.str();
+
+ std::vector<string> components;
+ boost::split(components, buffer, boost::is_any_of(" ,\n"));
+
+ // expected + number of timestamps (one per log statement) + trailing newline of last statement
+ BOOST_REQUIRE_EQUAL(components.size(), N_EXPECTED + 6 + 1);
+
+ std::vector<std::string>::const_iterator componentIter = components.begin();
+ for (size_t i = 0; i < N_EXPECTED; ++i)
+ {
+ // timestamp LOG_LEVEL: [ModuleName] message\n
+
+ const string& timestamp = *componentIter;
+ // std::cout << "timestamp = " << timestamp << std::endl;
+ ++componentIter;
+
+ size_t timeDelimiterPosition = timestamp.find(".");
+
+ BOOST_REQUIRE_NE(string::npos, timeDelimiterPosition);
+
+ string secondsString = timestamp.substr(0, timeDelimiterPosition);
+ string usecondsString = timestamp.substr(timeDelimiterPosition + 1);
+
+ microseconds::rep extractedTime =
+ ONE_SECOND * boost::lexical_cast<microseconds::rep>(secondsString) +
+ boost::lexical_cast<microseconds::rep>(usecondsString);
+
+ // std::cout << "before=" << before << " extracted=" << extractedTime << " after=" << after << std::endl;
+
+ BOOST_REQUIRE(before <= extractedTime);
+ BOOST_REQUIRE(extractedTime <= after);
+
+ // LOG_LEVEL:
+ BOOST_REQUIRE_EQUAL(*componentIter, EXPECTED[i]);
+ ++componentIter;
+ ++i;
+
+ // [ModuleName]
+ BOOST_REQUIRE_EQUAL(*componentIter, EXPECTED[i]);
+ ++componentIter;
+ ++i;
+
+ const string& message = *componentIter;
+
+ // std::cout << "message = " << message << std::endl;
+
+ // add back the newline that we split on
+ BOOST_REQUIRE_EQUAL(message + "\n", EXPECTED[i]);
+ ++componentIter;
+ }
}
@@ -277,12 +622,12 @@
void
writeLogs()
{
- NFD_LOG_TRACE("trace message JHGFDSR^1");
- NFD_LOG_DEBUG("debug message IGg2474fdksd fo " << 15 << 16 << 17);
- NFD_LOG_WARN("warning message XXXhdhd11" << 1 << "x");
- NFD_LOG_INFO("info message Jjxjshj13");
- NFD_LOG_ERROR("error message !#$&^%$#@");
- NFD_LOG_FATAL("fatal message JJSjaamcng");
+ NFD_LOG_TRACE("trace-message-JHGFDSR^1");
+ NFD_LOG_DEBUG("debug-message-IGg2474fdksd-fo-" << 15 << 16 << 17);
+ NFD_LOG_WARN("warning-message-XXXhdhd11" << 1 <<"x");
+ NFD_LOG_INFO("info-message-Jjxjshj13");
+ NFD_LOG_ERROR("error-message-!#$&^%$#@");
+ NFD_LOG_FATAL("fatal-message-JJSjaamcng");
}
private:
@@ -294,30 +639,163 @@
BOOST_FIXTURE_TEST_CASE(GenericInTemplatedClass, InClassTemplateLogger<bool>)
{
+ using namespace ndn::time;
+ using std::string;
+
+ const ndn::time::microseconds::rep ONE_SECOND = 1000000;
+
+ microseconds::rep before =
+ duration_cast<microseconds>(system_clock::now().time_since_epoch()).count();
+
writeLogs();
- BOOST_CHECK_EQUAL(m_buffer.str(),
- "TRACE: [GenericInClassTemplateLogger] trace message JHGFDSR^1\n"
- "DEBUG: [GenericInClassTemplateLogger] debug message IGg2474fdksd fo 151617\n"
- "WARNING: [GenericInClassTemplateLogger] warning message XXXhdhd111x\n"
- "INFO: [GenericInClassTemplateLogger] info message Jjxjshj13\n"
- "ERROR: [GenericInClassTemplateLogger] error message !#$&^%$#@\n"
- "FATAL: [GenericInClassTemplateLogger] fatal message JJSjaamcng\n"
- );
+ microseconds::rep after =
+ duration_cast<microseconds>(system_clock::now().time_since_epoch()).count();
+
+ const string EXPECTED[] =
+ {
+ "TRACE:", "[GenericInClassTemplateLogger]", "trace-message-JHGFDSR^1\n",
+ "DEBUG:", "[GenericInClassTemplateLogger]", "debug-message-IGg2474fdksd-fo-151617\n",
+ "WARNING:", "[GenericInClassTemplateLogger]", "warning-message-XXXhdhd111x\n",
+ "INFO:", "[GenericInClassTemplateLogger]", "info-message-Jjxjshj13\n",
+ "ERROR:", "[GenericInClassTemplateLogger]", "error-message-!#$&^%$#@\n",
+ "FATAL:", "[GenericInClassTemplateLogger]", "fatal-message-JJSjaamcng\n",
+ };
+
+ const size_t N_EXPECTED = sizeof(EXPECTED) / sizeof(string);
+
+ const string buffer = m_buffer.str();
+
+ std::vector<string> components;
+ boost::split(components, buffer, boost::is_any_of(" ,\n"));
+
+ // expected + number of timestamps (one per log statement) + trailing newline of last statement
+ BOOST_REQUIRE_EQUAL(components.size(), N_EXPECTED + 6 + 1);
+
+ std::vector<std::string>::const_iterator componentIter = components.begin();
+ for (size_t i = 0; i < N_EXPECTED; ++i)
+ {
+ // timestamp LOG_LEVEL: [ModuleName] message\n
+
+ const string& timestamp = *componentIter;
+ // std::cout << "timestamp = " << timestamp << std::endl;
+ ++componentIter;
+
+ size_t timeDelimiterPosition = timestamp.find(".");
+
+ BOOST_REQUIRE_NE(string::npos, timeDelimiterPosition);
+
+ string secondsString = timestamp.substr(0, timeDelimiterPosition);
+ string usecondsString = timestamp.substr(timeDelimiterPosition + 1);
+
+ microseconds::rep extractedTime =
+ ONE_SECOND * boost::lexical_cast<microseconds::rep>(secondsString) +
+ boost::lexical_cast<microseconds::rep>(usecondsString);
+
+ // std::cout << "before=" << before << " extracted=" << extractedTime << " after=" << after << std::endl;
+
+ BOOST_REQUIRE(before <= extractedTime);
+ BOOST_REQUIRE(extractedTime <= after);
+
+ // LOG_LEVEL:
+ BOOST_REQUIRE_EQUAL(*componentIter, EXPECTED[i]);
+ ++componentIter;
+ ++i;
+
+ // [ModuleName]
+ BOOST_REQUIRE_EQUAL(*componentIter, EXPECTED[i]);
+ ++componentIter;
+ ++i;
+
+ const string& message = *componentIter;
+
+ // std::cout << "message = " << message << std::endl;
+
+ // add back the newline that we split on
+ BOOST_REQUIRE_EQUAL(message + "\n", EXPECTED[i]);
+ ++componentIter;
+ }
}
+
BOOST_FIXTURE_TEST_CASE(SpecializedInTemplatedClass, InClassTemplateLogger<int>)
{
+ using namespace ndn::time;
+ using std::string;
+
+ const ndn::time::microseconds::rep ONE_SECOND = 1000000;
+
+ microseconds::rep before =
+ duration_cast<microseconds>(system_clock::now().time_since_epoch()).count();
+
writeLogs();
- BOOST_CHECK_EQUAL(m_buffer.str(),
- "TRACE: [IntInClassLogger] trace message JHGFDSR^1\n"
- "DEBUG: [IntInClassLogger] debug message IGg2474fdksd fo 151617\n"
- "WARNING: [IntInClassLogger] warning message XXXhdhd111x\n"
- "INFO: [IntInClassLogger] info message Jjxjshj13\n"
- "ERROR: [IntInClassLogger] error message !#$&^%$#@\n"
- "FATAL: [IntInClassLogger] fatal message JJSjaamcng\n"
- );
+ microseconds::rep after =
+ duration_cast<microseconds>(system_clock::now().time_since_epoch()).count();
+
+ const string EXPECTED[] =
+ {
+ "TRACE:", "[IntInClassLogger]", "trace-message-JHGFDSR^1\n",
+ "DEBUG:", "[IntInClassLogger]", "debug-message-IGg2474fdksd-fo-151617\n",
+ "WARNING:", "[IntInClassLogger]", "warning-message-XXXhdhd111x\n",
+ "INFO:", "[IntInClassLogger]", "info-message-Jjxjshj13\n",
+ "ERROR:", "[IntInClassLogger]", "error-message-!#$&^%$#@\n",
+ "FATAL:", "[IntInClassLogger]", "fatal-message-JJSjaamcng\n",
+ };
+
+ const size_t N_EXPECTED = sizeof(EXPECTED) / sizeof(string);
+
+ const string buffer = m_buffer.str();
+
+ std::vector<string> components;
+ boost::split(components, buffer, boost::is_any_of(" ,\n"));
+
+ // expected + number of timestamps (one per log statement) + trailing newline of last statement
+ BOOST_REQUIRE_EQUAL(components.size(), N_EXPECTED + 6 + 1);
+
+ std::vector<std::string>::const_iterator componentIter = components.begin();
+ for (size_t i = 0; i < N_EXPECTED; ++i)
+ {
+ // timestamp LOG_LEVEL: [ModuleName] message\n
+
+ const string& timestamp = *componentIter;
+ // std::cout << "timestamp = " << timestamp << std::endl;
+ ++componentIter;
+
+ size_t timeDelimiterPosition = timestamp.find(".");
+
+ BOOST_REQUIRE_NE(string::npos, timeDelimiterPosition);
+
+ string secondsString = timestamp.substr(0, timeDelimiterPosition);
+ string usecondsString = timestamp.substr(timeDelimiterPosition + 1);
+
+ microseconds::rep extractedTime =
+ ONE_SECOND * boost::lexical_cast<microseconds::rep>(secondsString) +
+ boost::lexical_cast<microseconds::rep>(usecondsString);
+
+ // std::cout << "before=" << before << " extracted=" << extractedTime << " after=" << after << std::endl;
+
+ BOOST_REQUIRE(before <= extractedTime);
+ BOOST_REQUIRE(extractedTime <= after);
+
+ // LOG_LEVEL:
+ BOOST_REQUIRE_EQUAL(*componentIter, EXPECTED[i]);
+ ++componentIter;
+ ++i;
+
+ // [ModuleName]
+ BOOST_REQUIRE_EQUAL(*componentIter, EXPECTED[i]);
+ ++componentIter;
+ ++i;
+
+ const string& message = *componentIter;
+
+ // std::cout << "message = " << message << std::endl;
+
+ // add back the newline that we split on
+ BOOST_REQUIRE_EQUAL(message + "\n", EXPECTED[i]);
+ ++componentIter;
+ }
}
BOOST_AUTO_TEST_SUITE_END()