rosconsole: Reduce duplicate log messages in rosconsole

[dirk-thomas]

From @ablasdel on January 8, 2013 22:39

When things go wrong on a running robot (both real and in simulation) many components output warning/error messages repeatedly to the console until killed. This is especially problematic for components that run at high rates, such as move_base, because they can overwhelm the terminal to the point that you have to wait a while before a ctrl-c has an effect (especially true on slow laptops and flaky wifi!).

This patch is a first stab at reducing the number of repeat messages. It works by allowing the initial output of a message and then counting the number of times the message is repeated. It will then output the number of repeats and the message once a second or when a different message is logged. File logging is not currently affected, though I'm thinking about applying this there too.

migration of trac ticket 4055:
https://code.ros.org/trac/ros/ticket/4055

change history (for attachements see first comment):
Changed 3 months ago by kbogert

attachment ros_console_limit_repeats.patch added
Changed 3 months ago by dthomas

Your patch adds throttling for once specific appender. There are two drawbacks with that approach: - throttling should potentially affect all appenders - some log messages should not be throttled if the source decides that this is better

Therefore ROS provides specific logging macros with the suffix _THROTTLE ( http://www.ros.org/wiki/roscpp/Overview/Logging). It enables the source of the log message to specify a specific max rate for publishing that message. Is there a reason why that already existing method is not sufficient?

Changed 3 months ago by kbogert

The THROTTLE macros would work if all sources used it, they do not and shouldn't necessarily. The problem specifically is with flooding the console with too many messages to read and/or slowing down the terminal to the point that it's impossible to interact with. I would consider adding throttling to the other appenders if they also have a negative effect on some portion of the system due to repeat messages. However, in the case of file logs, for instance, it's likely that you want all messages with accurate timestamps for debugging after the fact.

To use the THROTTLE macro the source would have to know that no one wants to hear a message as often as it is being generated. Here we're making a practical concession that no one can read "missed desired rate" messages as they fly by at 30hz, printing all of them will likely cause you to miss more important messages, and you still want to receive other messages from the problem component of the same logging level (so filtering them at with log4cxx is not an option). This patch allows you to know that the repeat message is happening and at what rate without flooding your console to do so.

Copied from original issue: ros/ros_comm#68

[dirk-thomas]

From @ablasdel on January 8, 2013 22:39

content of ros_console_limit_repeats.patch:

--- rosconsole.cpp  2012-10-18 15:05:59.591177990 -0400
+++ new/rosconsole.cpp  2012-10-18 15:04:47.539177776 -0400
@@ -389,11 +389,88 @@
   {
   }

+  ROSConsoleStdioAppender() : log4cxx::AppenderSkeleton()
+  {
+      lastMessageCounter = 0;
+      lastMessageTime = ros::Time(0);
+      lastMessageWallTime = ros::WallTime(0);
+      lastEvent = 0;
+  }
+  ROSConsoleStdioAppender(const log4cxx::LayoutPtr &layout) : log4cxx::AppenderSkeleton(layout)
+  {
+      lastMessageCounter = 0;
+      lastMessageTime = ros::Time(0);
+      lastMessageWallTime = ros::WallTime(0);
+      lastEvent = 0;
+  }
+
 protected:
-  virtual void append(const log4cxx::spi::LoggingEventPtr& event, 
+  virtual void append(const log4cxx::spi::LoggingEventPtr& event,
                       log4cxx::helpers::Pool&)
   {
+
+      if (lastEvent != 0)
+      {
+         if (event->getMessage().compare(lastEvent->getMessage()) == 0)
+         {
+            // If it's been more than a second since our last print, print out a counter message
+
+            float diff;
+            if (ros::Time::isValid() && ros::Time::isSimTime())
+            {
+                diff = (ros::Time::now() - lastMessageTime).toSec();
+            } else
+            {
+                diff = (ros::WallTime::now() - lastMessageWallTime).toSec();
+            }
+
+            if (diff > 1.0 && lastMessageCounter > 0)
+            {
+                std::stringstream ss;
+                ss << "Repeated " << lastMessageCounter << " times: " << lastEvent->getMessage();
+                log4cxx::spi::LoggingEventPtr newevent(new log4cxx::spi::LoggingEvent(event->getLoggerName(), event->getLevel(), ss.str(), event->getLocationInformation()));
+
+                g_formatter.print(newevent);
+
+                lastMessageCounter = 0;
+                if (ros::Time::isValid() && ros::Time::isSimTime())
+                {
+                  lastMessageTime = ros::Time::now();
+                }
+                else
+                {
+                  lastMessageWallTime = ros::WallTime::now();
+                }
+            } else
+            {
+                lastMessageCounter ++;
+
+            }
+            return;
+
+          } else if (lastMessageCounter > 0)
+          {
+                std::stringstream ss;
+                ss << "Repeated " << lastMessageCounter << " times: " << lastEvent->getMessage();
+                log4cxx::spi::LoggingEventPtr newevent(new log4cxx::spi::LoggingEvent(lastEvent->getLoggerName(), lastEvent->getLevel(), ss.str(), lastEvent->getLocationInformation()));
+
+                g_formatter.print(newevent);
+
+          }
+      }
+
     g_formatter.print(event);
+
+    lastEvent = event;
+    lastMessageCounter = 0;
+    if (ros::Time::isValid() && ros::Time::isSimTime())
+    {
+      lastMessageTime = ros::Time::now();
+    }
+    else
+    {
+      lastMessageWallTime =  ros::WallTime::now();
+    }
   }

   virtual void close()
@@ -403,6 +480,13 @@
   {
     return false;
   }
+
+  log4cxx::spi::LoggingEventPtr lastEvent;
+
+  int lastMessageCounter;
+  ros::Time lastMessageTime;
+  ros::WallTime lastMessageWallTime;
+
 };

 /**