rosmon_core: Adding verbosity filter feature

[Cartoonman]

Here's yet another filter I added to rosmon. This was a bit tricky to get proper, but the tl;dr is that this uses the fgColor value to determine the log level. The reason why I went this route was a couple of reasons:

• We already get fgColor and it's simple to implement.
• When I checked the raw strings, there are actually subtle control character differences between C++ and Python ROS console output for the same log levels, which makes any non-color based solution inherently more complex.

I added F6, F7, and F8 as keys to select the verbosity level. Currently I just have it set to display levels 1, 2, and 3, but if you want I can change it to show 'Low, Med, High' or some effect.

• 1 : Only WARN+ messages printed
• 2 : Only INFO+ messages printed
• 3 : DEBUG+ messages printed (all)

Also as a consequence of this, this inevitably adds to the already increasing size of the control bar. Something I thought of was to make the bar 'togglable', like with F1 or some key. This way we could have the default bar be just status messages (like Mute and Verbosity level) and if the user wants to see the controls, they can press F1 and a multi-level bar could appear with all options outlined.

If we want to do that that'll have to be a separate PR (I haven't written code for that, just my musings).

[xqms]

Interesting, thanks for the PR!

Finding the log severity by color seems a bit hacky to me. I would like to propose a simpler solution: we already capture stdout/stderr separately to support output=log. Only ROS_INFO and ROS_DEBUG go to stdout, all other severities log to stderr.

Maybe adding a key to hide stdout would be enough? Of course, we lose one level of granularity, but do you often have to hide warnings?

[Personal opinion on node output: if a launch file output gets too verbose to read, I try to fix the involved nodes instead of filtering the output.
There's no excuse for hammering ROS_INFO and friends ;-)
INFO and above should only be used for non-recurring prints (or at least be heavily throttled).
That said, I get that it's useful to add filtering for third-party launch files/systems.]

[Cartoonman]

Maybe? I separated ROS_DEBUG and ROS_INFO partially because we typically run our nodes with ROS_INFO as the minimum visible level, and also because for roscpp, there's a plethora of debug messages printed by the underlying interface that we wouldn't typically want to see all the time (these messages certainly are not rate-limited), but sometimes we may need them to help diagnose networking issues with subscribers/services, so being able to tie higher-level publish calls with lower-level debug interface messages helps.

Regardless having a stderr-only mode would be universally helpful for most users I think, esp for a large number of nodes in one roslaunch context.

Another thing that we might be able to do now that I think about it, is to just use the underlying set_logger and get_logger rosservices that are paired with every rosnode launched (at least for roscpp), and set the desired log level this way. Might take a bit more work to implement though, since you'll have to get the list of active rosservices, filter by get_logger and set_logger, and somehow tie the log-level with the node id in question. What do you think?

[xqms]

Maybe? I separated ROS_DEBUG and ROS_INFO partially because ...

At least in the default configuration, ROS_DEBUG messages are not printed by the nodes. You either need a rosconsole configuration file or set it interactively using rqt_logger_level / service calls. So in my mind it doesn't make much sense to filter these in rosmon, since you have to explicitly enable them anyway (and nobody will keep them on longer than required ^^). Thoughts?

Regardless having a stderr-only mode would be universally helpful for most users I think, esp for a large number of nodes in one roslaunch context.

Yep, let's focus on that first.

Another thing that we might be able to do now that I think about it, is to just use the underlying set_logger and get_logger rosservices that are paired with every rosnode launched (at least for roscpp), and set the desired log level this way. Might take a bit more work to implement though, since you'll have to get the list of active rosservices, filter by get_logger and set_logger, and somehow tie the log-level with the node id in question. What do you think?

I thought about this as well. Well, we know the node name for all nodes, that's no problem. But logger names is a larger problem. Do we add a fancy selection UI? I think that would be too much for rosmon. So all we could do is something like "set all loggers in a particular node to level X". I think that's not very useful, since most of the time I want the default logger set to debug, but all the roscpp internals to INFO...

[Cartoonman]

So I took a look at the code and I couldn't really find where stdout/stderr were differentiated. I looked inside node_monitor.cpp and if I understood the cpp correctly, the communicate() function is what gets the output from each node and signals this message with the logMessageSignal() boost::signal function, which triggers ui::log(). The type of all of these messages is just LogEvent::Type::Raw since they're self encoded with ANSI color codes, and the output of printing these messages is just stdout anyway.

Am I missing something? I still don't see how else to differentiate WARN/ERROR from other types of messages without reading the ANSI color code. As far as I can tell you set up your own file descriptor in the node_monitor for each node so it comes in as just a single fd.

[xqms]

Oops, I thought that feature was in master already... But it seems I started working on it but never merged it. Sorry for misleading you ;)

I found the old branch:
https://github.com/xqms/rosmon/tree/feature/stdout_stderr

[Cartoonman]

Ah, that branch makes much more sense now. I rebased the branch on top of master (no conflicts so all good). Should I merge that branch into feature/verbosity_filter and work from that?

[xqms]

I just did the rebase as well ;) I noticed that it has failing unit tests - presumably because it tests node->isMuted() instead of node->showStdout() in the tests for output=log. So those would need to be fixed.

Yep, if you like merge that into your branch and we will treat it as one PR.

[Cartoonman]

Ok i pulled in the stderr branch into this branch and added new filter logic on top for verbosity filter. Now it's just F8 to toggle WARN+ output, and the logic is such that if event.showStdout is false, this supersedes the effect of this filter.

Doublecheck the unittests for stdout_stderr. I tried to fill in what I think you were intending for the checks. It passes, I just didn't know how isMuted() now ties in with stdoutDisplayed() and if you wanted to test both in each test case.

[xqms]

Everything looks good, thanks for your work!

Yep, the unit tests should just test stdoutDisplayed() - muting has nothing to do with the launch config now and is purely a UI feature.