Discussion: Proposal for distinction between dtwarn, dterr, and dtmsg

[mxgrey]

I like the fact that we have three different styles of terminal output, although sometimes it seems ambiguous which one should be used at any time. I've given it some thought, and here is a proposal that I've come up with for how they should each be used:

dterr should indicate that the user has instructed DART to do something that would literally result in undefined behavior (in the sense of ISO C++ rules) if we allowed it to happen. Examples would include giving a nullptr to a DART function that is not designed to accept nullptrs, or requesting an out-of-bounds entry from an array.

dtwarn should indicate that the user has instructed DART to do something that would not result in "undefined behavior", but which will likely result in unexpected or undesirable behavior from DART. An example would be setting a command value that exceeds the maximum permitted value.

dtmsg should be used for things that wouldn't be harmful, but might be important for the user to know. For example, when a Skeleton changes the name of a new joint because its name was already taken by a previous joint, or if the user attempts to add a single Skeleton to a world twice.

[psigen]

For what it's worth, many logging frameworks use the following logging level conventions: https://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/Level.html

It seems like you are informally converging on these streams meaning the ERROR, WARN, and INFO levels. You can consider having some of the others, or at least formally matching their semantics.

Level	Description
FATAL	The FATAL level designates very severe error events that will presumably lead the application to abort.
ERROR	The ERROR level designates error events that might still allow the application to continue running.
WARN	The WARN level designates potentially harmful situations.
INFO	The INFO level designates informational messages that highlight the progress of the application at coarse-grained level.
DEBUG	The DEBUG Level designates fine-grained informational events that are most useful to debug an application.
TRACE	The TRACE Level designates finer-grained informational events than the DEBUG

[mxgrey]

I've thought about debug and trace messages, but the trouble is that most of DART's functionality is meant to be run in very tight loops, and performance is a big priority. The raw amount of information flooding that would be produced by any kind of message that gets hit in the middle of a loop would be cumbersome and unhelpful in most plausible situations. Not to mention, all the buffering and flushing would kill performance, and performance is already painfully slow when running in debug mode.

So it's hard for me to see where exactly debugging and trace messages would fit into DART, except maybe when things are winding up and winding down.

[psigen]

Usually, logging frameworks (at least the good ones) solve this by using preprocessor tricks to remove logging under a certain level at compile time as specified by a compile flag. This is separate from the runtime log level, which can be dynamically adjusted.

Here is one example of some of these tricks: http://stackoverflow.com/questions/19415845/a-better-log-macro-using-template-metaprogramming

But actually, in this case I was just referring to whether it made sense to name dterr to dterror and dtmsg to dtinfo and if there was a need for dtfatal (of course not, DART should never crash!).

[mkoval]

Most logging frameworks have minimal overhead on disabled loggers. There are typically two ways of disabling them: (1) zero overhead at compile time and (2) minimal overhead, typically a single branch, at runtime. You may not want to leave DEBUG or TRACE messages enabled while running on a real system, but they sure are useful while debugging.

Also, these levels may make sense in user application code. For example, we make heavy use of the DEBUG level to print out information while initializing a planner. This is invaluable for diagnosing why planning failed, but is far too spammy to leave enabled by default.

I'm not sure if you intend these loggers to be used outside of the DART core, though.

[mxgrey]

I'm not sure if you intend these loggers to be used outside of the DART core, though.

Truthfully, I don't think dterr, dtwarn, and dtmsg would really qualify as loggers. They're just macros for printing terminal messages with pretty colors, and they make it clear where the messages are originating within the DART source code.

Usually, logging frameworks (at least the good ones) solve this by using preprocessor tricks to remove logging under a certain level at compile time as specified by a compile flag.

I would definitely consider debug and trace logs that get masked at compile-time. But I think we'd still have the "information overload" issue unless we could come up with a clear and meaningful categorization of all the different types of debug and trace messages, and have a way to enable/disable specific categories. Like, if I'm debugging the joint forces, then I don't want to be flooded by messages about everything that's going on with the forward kinematics if I trust that the forward kinematics is doing the right thing.

It's definitely worth thinking about, but I'd put it at very low priority at the moment, since I don't think there have been any major challenges with debugging recently.

[jslee02]

As a reference, there are ROS' verbosity levels. They are similar to the apache's convention @psigen mentioned above.

[psigen]

I've had a few thoughts on this:

Overridable logging templates/macros: Just as an example (not proposing macros as a solution), one of the packages we've used standardizes the logging call macros to the point where client code can redefine/override the default implementation (which is just sending it to iostream).

Here is an example of passing logging to OpenRAVE when we are using it as an OpenRAVE plugin: https://github.com/personalrobotics/or_parabolicsmoother/blob/master/include/or_parabolicsmoother/Config.h#L13

If it were possible, a cleaned-up version of this mechanism would allow DART to default to realtime-safe print mechanisms, while allowing client libraries and users to flexibly redirect that output into other systems like ROS_CONSOLE or log4cxx.

Useful logging context: Another example we can refer to is the LoggingEvent class that is used by log4cxx: https://logging.apache.org/log4cxx/apidocs/classlog4cxx_1_1spi_1_1_logging_event.html

This structure stores all the information that is ever passed to the log4cxx handlers. I think this is a pretty good upper bound on what we would ever need DART logging to do. (Also note that log4cxx::LogEvents store their message format string and context objects separately, to allow the handler to do the actual message rendering on demand.)

If we construct them carefully, it may be possible to have the DART logging statements collect as much of this as is constexpr, but only have the information be evaluated when it is used in a particular logging implementation.

This means that more complex logging implementations like a log4cxx adapter can have more complex branching logic: e.g. "suppress dart::common warnings, and print dart::dynamics debug", while less complex ones (like a default iostream printer) can just suppress everything under WARN or whatever.

Desirability of compile-time cleanup of log statements: A big caveat is that completely eliminating logging statements at compile time can make it harder to debug issues in downstream code. Consider the case where a client library is passing a bad argument to something in DART. If a user is linking against a .deb that has been compiled with log_level=INFO, there is no way for them to see DEBUG messages that might print detailed information about where the argument might be deviating from expected.

At best, they can put new logging statements in their code around the DART calls and hope to catch the problem, but this can get really tricky if an argument looks alright until it gets unpacked or some subsequent internal DART operation happens.

It might make sense to just use a bit of common sense here: e.g. we might set things up to compile out TRACE but leave DEBUG as a branch, then specifically use TRACE statements inside very tight loops.

[jslee02]

1593 added basic logging features based on this discussion, and I hope most of the points are captured by it. Closing this issue for now, but will refer to this for further improvements. Thank you for all the good points made in this discussion!