From eb1f3327abd166b394ad19b0db1ca518e28c8dc1 Mon Sep 17 00:00:00 2001
From: Joseph Mirabel <jmirabel@laas.fr>
Date: Fri, 31 Jan 2020 15:45:34 +0100
Subject: [PATCH] Fix bugs related to loggers.

---
 include/dynamic-graph/logger.h | 31 ++++++------
 src/debug/logger.cpp           |  2 +-
 tests/debug-logger.cpp         | 90 ++++++++++++++++++++++++++--------
 3 files changed, 87 insertions(+), 36 deletions(-)

diff --git a/include/dynamic-graph/logger.h b/include/dynamic-graph/logger.h
index 3c46851..b7552b5 100644
--- a/include/dynamic-graph/logger.h
+++ b/include/dynamic-graph/logger.h
@@ -27,17 +27,17 @@ namespace dynamicgraph {
 /** Enum representing the different kind of messages.
  */
 enum MsgType {
-  MSG_TYPE_TYPE_BITS      = 1<<0 | 1<<1 | 1<<2 | 1<<3, // 15
-  MSG_TYPE_STREAM_BIT     = 1<<4,                      // 16
-
-  MSG_TYPE_DEBUG          = 1<<0,                      // 1
-  MSG_TYPE_INFO           = 1<<1,                      // 2
-  MSG_TYPE_WARNING        = 1<<2,                      // 4
-  MSG_TYPE_ERROR          = 1<<3,                      // 8
-  MSG_TYPE_DEBUG_STREAM   = MSG_TYPE_DEBUG   | 1<<4,   // 17
-  MSG_TYPE_INFO_STREAM    = MSG_TYPE_INFO    | 1<<4,   // 18
-  MSG_TYPE_WARNING_STREAM = MSG_TYPE_WARNING | 1<<4,   // 20
-  MSG_TYPE_ERROR_STREAM   = MSG_TYPE_ERROR   | 1<<4    // 24
+  MSG_TYPE_TYPE_BITS      = 1<<0 | 1<<1 | 1<<2 | 1<<3,                // 15
+  MSG_TYPE_STREAM_BIT     = 1<<4,                                     // 16
+
+  MSG_TYPE_DEBUG          = 1<<3,                                     // 1
+  MSG_TYPE_INFO           = 1<<2,                                     // 2
+  MSG_TYPE_WARNING        = 1<<1,                                     // 4
+  MSG_TYPE_ERROR          = 1<<0,                                     // 8
+  MSG_TYPE_DEBUG_STREAM   = MSG_TYPE_DEBUG   | MSG_TYPE_STREAM_BIT,   // 17
+  MSG_TYPE_INFO_STREAM    = MSG_TYPE_INFO    | MSG_TYPE_STREAM_BIT,   // 18
+  MSG_TYPE_WARNING_STREAM = MSG_TYPE_WARNING | MSG_TYPE_STREAM_BIT,   // 20
+  MSG_TYPE_ERROR_STREAM   = MSG_TYPE_ERROR   | MSG_TYPE_STREAM_BIT    // 24
 };
 } // namespace dynamicgraph
 
@@ -182,7 +182,9 @@ enum LoggerVerbosity {
 ///
 /// \endcode
 ///
-///
+/// \todo remove m_timeSample and streamPrintPeriod to rather use a simple
+///       integer counting the number of calls. This will achieve exactly the
+///       same behaviour without rouding numerical errors.
 class Logger {
 public:
   /** Constructor */
@@ -198,7 +200,7 @@ public:
   /** Get an output stream independently of the debug level.
    */
   RTLoggerStream stream() {
-    return ::dynamicgraph::RealTimeLogger::instance().emptyStream();
+    return ::dynamicgraph::RealTimeLogger::instance().front();
   }
 
   /** Print the specified message on standard output if the verbosity level
@@ -271,7 +273,8 @@ protected:
    *        is updated.
    */
   bool acceptMsg (MsgType m, const std::string& lineId) {
-    if ((m & MSG_TYPE_TYPE_BITS) < m_lv)
+    // If more verbose than the current verbosity level
+    if ((m & MSG_TYPE_TYPE_BITS) > m_lv)
       return false;
 
     // if print is allowed by current verbosity level
diff --git a/src/debug/logger.cpp b/src/debug/logger.cpp
index 10c30c0..c132f26 100644
--- a/src/debug/logger.cpp
+++ b/src/debug/logger.cpp
@@ -76,8 +76,8 @@ bool Logger::checkStreamPeriod(const std::string &lineId) {
 
   // if counter is greater than 0 then decrement it and do not print
   double &counter = result.first->second;
+  counter -= m_timeSample;
   if (counter > 0.0) {
-    counter -= m_timeSample;
     return false;
   } else // otherwise reset counter and print
     counter = m_streamPrintPeriod;
diff --git a/tests/debug-logger.cpp b/tests/debug-logger.cpp
index da1759b..296897b 100644
--- a/tests/debug-logger.cpp
+++ b/tests/debug-logger.cpp
@@ -31,38 +31,86 @@ public:
   explicit CustomEntity(const std::string &n) : Entity(n) {
     logger_.setTimeSample(0.001);
     logger_.setStreamPrintPeriod(0.005);
+
+    logger_.setVerbosity(VERBOSITY_NONE);
+    BOOST_CHECK_EQUAL(logger_.getVerbosity(), VERBOSITY_NONE);
+    BOOST_CHECK( logger_.stream(MSG_TYPE_DEBUG  ).isNull());
+    BOOST_CHECK( logger_.stream(MSG_TYPE_INFO   ).isNull());
+    BOOST_CHECK( logger_.stream(MSG_TYPE_WARNING).isNull());
+    BOOST_CHECK( logger_.stream(MSG_TYPE_ERROR  ).isNull());
+
+    logger_.setVerbosity(VERBOSITY_ERROR);
+    BOOST_CHECK_EQUAL(logger_.getVerbosity(), VERBOSITY_ERROR);
+    BOOST_CHECK( logger_.stream(MSG_TYPE_DEBUG  ).isNull());
+    BOOST_CHECK( logger_.stream(MSG_TYPE_INFO   ).isNull());
+    BOOST_CHECK( logger_.stream(MSG_TYPE_WARNING).isNull());
+    BOOST_CHECK(!logger_.stream(MSG_TYPE_ERROR  ).isNull());
+
+    logger_.setVerbosity(VERBOSITY_WARNING_ERROR);
+    BOOST_CHECK_EQUAL(logger_.getVerbosity(), VERBOSITY_WARNING_ERROR);
+    BOOST_CHECK( logger_.stream(MSG_TYPE_DEBUG  ).isNull());
+    BOOST_CHECK( logger_.stream(MSG_TYPE_INFO   ).isNull());
+    BOOST_CHECK(!logger_.stream(MSG_TYPE_WARNING).isNull());
+    BOOST_CHECK(!logger_.stream(MSG_TYPE_ERROR  ).isNull());
+
+    logger_.setVerbosity(VERBOSITY_INFO_WARNING_ERROR);
+    BOOST_CHECK_EQUAL(logger_.getVerbosity(), VERBOSITY_INFO_WARNING_ERROR);
+    BOOST_CHECK( logger_.stream(MSG_TYPE_DEBUG  ).isNull());
+    BOOST_CHECK(!logger_.stream(MSG_TYPE_INFO   ).isNull());
+    BOOST_CHECK(!logger_.stream(MSG_TYPE_WARNING).isNull());
+    BOOST_CHECK(!logger_.stream(MSG_TYPE_ERROR  ).isNull());
+
     logger_.setVerbosity(VERBOSITY_ALL);
-    LoggerVerbosity alv = logger_.getVerbosity();
-    BOOST_CHECK(alv == VERBOSITY_ALL);
+    BOOST_CHECK_EQUAL(logger_.getVerbosity(), VERBOSITY_ALL);
+    BOOST_CHECK(!logger_.stream(MSG_TYPE_DEBUG  ).isNull());
+    BOOST_CHECK(!logger_.stream(MSG_TYPE_INFO   ).isNull());
+    BOOST_CHECK(!logger_.stream(MSG_TYPE_WARNING).isNull());
+    BOOST_CHECK(!logger_.stream(MSG_TYPE_ERROR  ).isNull());
   }
 
   ~CustomEntity() {}
   void testDebugTrace() {
-    sendMsg("This is a message of level MSG_TYPE_DEBUG", MSG_TYPE_DEBUG);
-    sendMsg("This is a message of level MSG_TYPE_INFO", MSG_TYPE_INFO);
-    sendMsg("This is a message of level MSG_TYPE_WARNING", MSG_TYPE_WARNING);
-    sendMsg("This is a message of level MSG_TYPE_ERROR", MSG_TYPE_ERROR);
-    sendMsg("This is a message of level MSG_TYPE_DEBUG_STREAM",
-            MSG_TYPE_DEBUG_STREAM);
-    sendMsg("This is a message of level MSG_TYPE_INFO_STREAM",
-            MSG_TYPE_INFO_STREAM);
-    sendMsg("This is a message of level MSG_TYPE_WARNING_STREAM",
-            MSG_TYPE_WARNING_STREAM);
-    sendMsg("This is a message of level MSG_TYPE_ERROR_STREAM",
-            MSG_TYPE_ERROR_STREAM);
+    logger_.stream(MSG_TYPE_DEBUG)
+      << "This is a message of level MSG_TYPE_DEBUG\n";
+    dynamicgraph::RealTimeLogger::instance().spinOnce();
+    logger_.stream(MSG_TYPE_INFO)
+      << "This is a message of level MSG_TYPE_INFO\n";
+    dynamicgraph::RealTimeLogger::instance().spinOnce();
+    logger_.stream(MSG_TYPE_WARNING)
+      << "This is a message of level MSG_TYPE_WARNING\n";
+    dynamicgraph::RealTimeLogger::instance().spinOnce();
+    logger_.stream(MSG_TYPE_ERROR)
+      << "This is a message of level MSG_TYPE_ERROR\n";
+    dynamicgraph::RealTimeLogger::instance().spinOnce();
+    logger_.stream(MSG_TYPE_DEBUG_STREAM)
+      << "This is a message of level MSG_TYPE_DEBUG_STREAM\n";
+    dynamicgraph::RealTimeLogger::instance().spinOnce();
+    logger_.stream(MSG_TYPE_INFO_STREAM)
+      << "This is a message of level MSG_TYPE_INFO_STREAM\n";
+    dynamicgraph::RealTimeLogger::instance().spinOnce();
+    logger_.stream(MSG_TYPE_WARNING_STREAM)
+      << "This is a message of level MSG_TYPE_WARNING_STREAM\n";
+    dynamicgraph::RealTimeLogger::instance().spinOnce();
+    logger_.stream(MSG_TYPE_ERROR_STREAM)
+      << "This is a message of level MSG_TYPE_ERROR_STREAM\n";
     /* Add test toString */
+    dynamicgraph::RealTimeLogger::instance().spinOnce();
     double q = 1.0;
-    sendMsg("Value to display: " + toString(q));
+    logger_.stream() << "Value to display: " + toString(q) << '\n';
+    dynamicgraph::RealTimeLogger::instance().spinOnce();
     std::vector<double> vq;
     vq.resize(3);
     vq[0] = 1.0;
     vq[1] = 2.0;
     vq[2] = 3.0;
-    sendMsg("Value to display: " + toString(vq));
-    sendMsg("Value to display: " + toString(vq, 3, 10));
+    logger_.stream(MSG_TYPE_INFO) << "Value to display: " << toString(vq) << '\n';
+    dynamicgraph::RealTimeLogger::instance().spinOnce();
+    logger_.stream(MSG_TYPE_INFO) << "Value to display: " << toString(vq, 3, 10) << '\n';
+    dynamicgraph::RealTimeLogger::instance().spinOnce();
     Eigen::Matrix<double, 3, 3> an_eig_m;
-    an_eig_m.Ones();
-    sendMsg("Value to display: " + toString(an_eig_m));
+    an_eig_m.setOnes();
+    logger_.stream(MSG_TYPE_INFO) << "Value to display: " << toString(an_eig_m) << '\n';
+    dynamicgraph::RealTimeLogger::instance().spinOnce();
     logger_.countdown();
   }
 };
@@ -84,8 +132,8 @@ BOOST_AUTO_TEST_CASE(debug_logger) {
 
   entity.setTimeSample(0.002);
   BOOST_CHECK_EQUAL(entity.getTimeSample(), 0.002);
-  entity.setStreamPrintPeriod(0.004);
-  BOOST_CHECK_EQUAL(entity.getStreamPrintPeriod(), 0.004);
+  entity.setStreamPrintPeriod(0.002);
+  BOOST_CHECK_EQUAL(entity.getStreamPrintPeriod(), 0.002);
 
   for (unsigned int i = 0; i < 10000; i++) {
     entity.testDebugTrace();
-- 
GitLab