Using YARP's internal logging instead of color-debug

[David-Estevez]

Hi!

I have just discovered that yarp has a logging system for the log messages (info, debug, warning, error...) of their yarp devices. We are using a similar system for our devices, based on color-debug, but I guess their logging system has better integration with yarp devices and other yarp mechanisms. Messages would also look more homogeneous if sent to stdout with the yarp logger instead of our own system.

The question is... should we use yarp's internal logging for our devices? or should we stick to the current color-debug system?

[PeterBowman]

I recall having come across some YARP utilities that understand and handle these logging streams, perhaps yarpdatadumper or yarpdataplayer. We can also mention the yarplogger program, but its documentation is scarce.

A few cons against migrating to YARP's logger:

• No colors (obviously).
• I don't see any option for enabling or disabling specific logging macros (you can control this via CMake with color-debug).
• ...?

Edit: regarding integration within YARP utilities, see robotology/QA#206.

[jgvictores]

Behold a screenshot of yarplogger.

[David-Estevez]

It reminds me of Android's Logcat, which is extremely useful for debugging on Android:

[PeterBowman]

No colors (obviously).

False, just set the YARP_COLORED_OUTPUT environment variable. See INFO and DEBUG logs below:

[PeterBowman]

A few more words about YARP log streams:

• six levels: trace (if YARP_TRACE_ENABLE=1), yInfo, yWarning, yDebug (enabled by default, turn off with YARP_DEBUG_ENABLE=0), yError, yFatal (calls std::exit) plus yAssert; see description at https://github.com/robotology/yarp/pull/252#issuecomment-60985641
• supports colors (if YARP_COLORED_OUTPUT=1)
• verbose output (if YARP_VERBOSE_OUTPUT=1) prints full paths and function signatures along with the line number
• broadcasts logs via YARP port (if YARP_FORWARD_LOG_ENABLE=1 or yarplogger was started)
• you can't disable specific log levels on the console
• nice yarplogger support, didn't try yarplogger-console yet
• recommended way of using yarplogger is to run apps/devices in a yarprun node (add --log); thus, every single output is recorded, whereas the YARP_FORWARD_LOG_ENABLE=1 way is unable to record non-YARP-logger lines
• supports two signatures per log level:
  • yDebug(...): much like printf(...), inserts a newline at the end
  • yDebug() << "value:" << val;: stream-like format, you can store this in a variable and append more stuff later within the same line of text (remember CD_DEBUG_NO_HEADER?)
• both signatures use C++ streams under the hood and call std::endl, which automatically flushes the output (we do this by hand in CD)
• yarplogger allows you to access logs for specific ports, show them on GUI with timestamps and nice colors (you can disable unwanted log levels), save specific logs to file or the entire log session

I'm a bit concerned about performance and the lack of Windows support (we can take advantage of previous experience on color-debug and submit a patch, though; see https://github.com/roboticslab-uc3m/color-debug/issues/5), but this is really cool. Shall we take this seriously and replace color-debug usage in our repos? Attaching screenshot for science, I made color-debug macros call YARP logger functions for this test:

Relevant sources:

• yarp/os/Log.h (include this if using yDebug(...) signature)
• yarp/os/LogStream.h (include this if using yDebug() << ... signature)
• Log.cpp

[PeterBowman]

YARP's logging system is undergoing a major overhaul. New features include fine-grained component-based tagging, and a lot more information accompanying each log event. See https://github.com/robotology/yarp/pull/2256 and linked dependent tickets. Also, https://github.com/robotology/yarp/pull/2258 contains a nice screenshot of new yarplogger in action.

I'm a bit concerned about performance and the lack of Windows support (we can take advantage of previous experience on color-debug and submit a patch, though; see roboticslab-uc3m/color-debug#5), but this is really cool.

Implemented in YARP 3.3.x, see https://github.com/robotology/yarp/pull/2076.

[PeterBowman]

YARP's logging system is undergoing a major overhaul.

This is nicely documented in http://www.yarp.it/yarp_logging.html (source).

[PeterBowman]

Currently running YARP 3.4 on TEO (https://github.com/roboticslab-uc3m/teo-hardware-issues/issues/58) with the new logging system and fancy colors enabled (https://github.com/roboticslab-uc3m/teo-developer-manual/commit/89c44dcfdc93e13dc49348774be1c48169151927).

Edit: rolled back to YARP 3.3 due to lack of Python 2 support.

[PeterBowman]

In view of the forthcoming replacement of color-debug with YARP logging goodies, I'm transferring this issue to a more horizontally focused location.

[PeterBowman]

Regular output


Yay, colors


Compact output (colored markers as log levels)


Verbose output


yarplogger GUI


[PeterBowman]

Further remarks (see https://github.com/roboticslab-uc3m/questions-and-answers/issues/90#issuecomment-517458703):

• Logging utilities support "components", i.e. additional tags that help identify the source of a log line. These are placed between the log level and the actual log message, e.g. [INFO] |yarp.os.Port| Port /bla active...
• Trace lines are dismissed by the compiler unless the project is build in Debug configuration. Besides, they need to be explicitly enabled through an environment variable. In non-verbose mode, trace lines also include the calling method's signature.
• For yarplogger to work, applications must be launched either via yarprun (initialized with the --log parameter) or command line plus an environment variable:
  • yarprun enables launching apps on remote machines, optionally piping the standard output to an xterm shell. If enabled, any kind of output is forwarded to the logger; this includes YARP logger utilities, printf, std::cout...
  • For yarplogger to collect application output when launched via command line, the YARP_FORWARD_LOG_ENABLE variable needs to be set to 1. This comes at the cost of using another port/thread and so on, and only YARP logger utilities can be piped (no other output is allowed).
• yarplogger has plenty of funcionalities, you can even unveil the full backtrace of each line if explicitly enabled, along with the absolute path of the source file, line number, calling method, etc.
• The CLI counterpart, yarplogger-console, is mostly an RPC interface for quickly inspecting available log streams and saving logs to file, which is of course also attainable via regular yarplogger.
• Stream macros are slightly less performant than the C-style ones, but also easier to use. For instance, there is an overload for printing a std::vector.
• We can emulate the old CD_XXX_NO_HEADER behavior with stream macros:

  std::vector<int> my_vector { 1, 2, 3, 4, 5 };
  {
    auto && _temp = yInfo();
    temp << "let's unpack a random vector:";
    for (int value : my_vector)
        _temp << value;
    _temp << "end";
  }
  // logger prints this before leaving the previous code block:
  // let's unpack a random vector: 1 2 3 4 5 end

  Although this is an artificial example as the following would also work: yInfo() << my_vector;

[PeterBowman]

I have given this a try at https://github.com/roboticslab-uc3m/openrave-yarp-plugins/commit/ea405eb126840438b386fcfbadb50174796f3559 and https://github.com/asrob-uc3m/yarp-devices/commit/c7f717c5b8dc025a383f6123f6aeb7133b0b3f6c. Some things to consider:

• Component names should be expressive, but not too long. I have chosen the schema namespace.main_class, much like core YARP does. I refused to add an intermediate term for the repository name (in my initial thoughts, the schema was github_org.github_repo.main_class) since that would make much longer names. Also, I assume name clashes should not be a thing in our orgs and, if necessary, a device/library/application can either refine its component name a bit or use more than one component.

• Log contents should be inspected one by one to make sure their original intention is preserved. Now, color-debug provides the file name and line number along with the log level and the log message. This filename is not always unique, but we manage to sort things out. At most, and when not in verbose mode, YARP logging utilities can only provide the component name via stdout/stderr. It is therefore a good idea to enhance existing log messages (where deemed convenient) so that they reflect the method or process currently going on.

• In the light of the thorough review I am anticipating in the previous point, it should be a good idea to check the logic of existing log levels (i.e. is this debug line really debug, or should I promote it to info level, and so on) and whether more log lines should be added. There is one particular case: we abuse CD_DEBUG for signalizing method entrance. It might be a good idea to switch to yTrace here, unless we really need them in Release config. Alternatively, throttling macros could be an option.

• As an additional side quest, search for std::couts and printfs that should be morphed into YARP logging macros. Also, make sure there are no newlines in the newly adapted YARP log lines, since those are automatically appended anyway.

[PeterBowman]

Note the --verbose option to yarpdev and several other companion utilities has been superseded by logging components (https://github.com/robotology/yarp/issues/2389#issuecomment-714720180). This may partially affect the solutions adopted in https://github.com/roboticslab-uc3m/questions-and-answers/issues/49. For instance, but not sure if a feature or a bug, now I can see all debug lines related to device configuration when issuing yarpdev --device EmulatedControlboard --name /fake, no YARP_VERBOSE=1 environment variable nor --verbose option involved (the former would additionally bloat the console with lots of comms-related notices). Besides, I need to look into lines such as this: rf.setVerbose(true).

[PeterBowman]

Color-debug is officially dead in most of roboticslab-uc3m (search) and in all asrob-uc3m repos (search). Leftovers:

• https://github.com/roboticslab-uc3m/WBPCwaiter (PhD thesis-related): demo-like repo ̶-̶ ̶h̶t̶t̶p̶s̶:̶/̶/̶g̶i̶t̶h̶u̶b̶.̶c̶o̶m̶/̶r̶o̶b̶o̶t̶i̶c̶s̶l̶a̶b̶-̶u̶c̶3̶m̶/̶t̶e̶o̶-̶b̶l̶e̶n̶d̶e̶r̶-̶m̶o̶d̶e̶l̶s̶:̶ ̶j̶u̶s̶t̶ ̶i̶n̶ ̶a̶ ̶s̶i̶n̶g̶l̶e̶ ̶C̶+̶+̶ ̶f̶i̶l̶e̶
• https://github.com/roboticslab-uc3m/bullet-yarp-plugins: abandoned?
• https://github.com/roboticslab-uc3m/xgnitive: abandoned?
• https://github.com/roboticslab-uc3m/footsteps: abandoned?

As soon as YARP 3.5 is released, I'm going to gradually drop support for YARP 3.3 and require 3.4, introducing logging components in our repositories. For now, the component-less scheme I followed mostly everywhere is:

yInfo() << "Bla bla bla" << value << "bla bla bla";

• A single sentence.
• Begins with uppercase letter.
• No ending period.

[PeterBowman]

As soon as YARP 3.5 is released, I'm going to gradually drop support for YARP 3.3 and require 3.4, introducing logging components in our repositories.

Done. Component names start with rl and reflect the main class of the library (or the library name itself), device or program, e.g. rl.YarpCloudUtils, rl.KdlSolver, rl.DumpCanBus. Components are declared and defined in their own .hpp/.cpp pair of files, then added to CMakeLists.txt (example). If only used in a single translation unit, they can be placed in an anonymous namespace and defined via YARP_LOG_COMPONENT (example).