Add named loggers to rospy #948

ggallagher01 · 2016-12-12T15:34:18Z

This change will create (named) child loggers under rospy.rosout. This allows for each named logger to have seperate verbosity setting, this will allow for two different verboisty settings for logging in a single node. Two named loggers can log to rosout at two different verbosity setings, which can help noisy debug logs.

dirk-thomas

Currently the patch fails to run the tests. Please iterate on this and run the tests locally.

dirk-thomas · 2016-12-12T17:50:49Z

clients/rospy/src/rospy/core.py

@@ -142,20 +143,37 @@ def rospyerr(msg, *args):
 def rospywarn(msg, *args):
    """Internal rospy client library warn logging"""
    _rospy_logger.warn(msg, *args)
-
-logdebug = logging.getLogger('rosout').debug


These variables are public API and can't be changed without breaking compatibility.

I think this is replaced in line 181 of the new file:

https://github.com/ros/ros_comm/pull/948/files#diff-84739190beb4f06aecd26a816f126e29R181

I'll take a look at it, I included a bunch of different commit here by accident. I'm cleaning up now

dirk-thomas · 2016-12-12T17:51:07Z

clients/rospy/src/rospy/core.py

@@ -109,7 +110,7 @@ def parse_rosrpc_uri(uri):
    @raise ParameterInvalid: if uri is not a valid ROSRPC URI
    """
    if uri.startswith(ROSRPC):
-        dest_addr = uri[len(ROSRPC):]            
+        dest_addr = uri[len(ROSRPC):]


Please avoid any unrelated white space changes in your PR (even if the current file might be "ugly"). It makes backporting changes across branches much more difficult.

Please take a look at the diff on the GitHub PR and update the PR to avoid any unnecessary changes.

sorry I thought I got them, I'll fix it up

I'll fix this again, I think the file has mixed line endings and my editor is trying to be helpful

dirk-thomas · 2017-01-17T18:53:08Z

My previous comment still applies to the updated change. Please avoid any unrelated white space changes in your PR.

dirk-thomas

Can you please add some unit tests (https://github.com/ros/ros_comm/blob/kinetic-devel/test/test_rospy/test/unit/test_rospy_core.py) covering the new funtionality.

dirk-thomas · 2017-01-26T23:09:31Z

clients/rospy/src/rospy/core.py

+def _get_digest(*args):
+    m = hashlib.md5()
+    for arg in args:
+        m.update(str(args))


Should this call update with arg instead of args?

yes, it should be arg instead of args. I'll fix that up.

Using MD5 for this seems like overkill. What about something like hash(tuple(*args + [str(msg)]))?

(Python's hashdoesn't do the right thing, so you can't use it directly, see ros/genpy#73)

That should work, we only want to know the content of the print has changed. I'll test it out tonight.

dirk-thomas · 2017-01-26T23:19:54Z

clients/rospy/src/rospy/core.py

+    logfunc = getattr(rospy_logger, level)
+
+    if throttle:
+        caller_id = _frame_record_to_caller_id(inspect.stack()[1])


Is 1 still correct now that the function is one level more nested?

I believe 2 is correct now because of the one more level down, I'll verify and fix that up

ggallagher01 · 2017-02-09T15:28:20Z

I resolved all the white space conflicts that my editor injected. Is there a standard line ending that each file should follow? I see this core.py has mixed line endings. I should have unit tests up tomorrow, I have a test program that I used for develpoment I'll port to the test framework.

mikepurvis · 2017-02-16T18:27:43Z

clients/rospy/src/rospy/core.py

+    try:
+        level = kwargs.pop('logger_level')
+    except KeyError:
+        level = None


For my curiosity, what does this achieve over, eg:

def _base_logger(msg, name=None, throttle=None, level=None, *args, **kwargs): rospy_logger = logging.getLogger('rosout') if name: rospy_logger = rospy_logger.getChild(name) logfunc = getattr(rospy_logger, level) if throttle: caller_id = _frame_record_to_caller_id(inspect.stack()[2]) _logging_throttle(caller_id, logfunc, throttle, msg, *args) else: logfunc(msg, *args)

I had the function using default values in one iteration but I believe i started failing tests and decided to use the keyword arguments instead. I'll rerun the tests and see if I can remember why I switched to using keyword args instead.

Looking back through my testing, I had a test case where using the named arguments for name, throttle and level (like above) would interfer with variable length arguments. This happened when testing out code that was using the existing public API, the named variables would end up taking some of the values from the multi length arguments.

Oh of course, that makes sense. In that case, maybe pass the default to pop rather than catching the exception. Eg:

def _base_logger(msg, *args, **kwargs): name = kwargs.pop('logger_name', None) throttle = kwargs.pop('logger_throttle', None) level = kwargs.pop('logger_level', None)

much cleaner, will change that

ggallagher01 · 2017-04-25T16:19:08Z

I believe all the the comments have been resolved, please let me know if there is anything else needed

ggallagher01 · 2017-05-10T02:13:52Z

cleaned up the review, looks better now. Tests are passing on my local machine.

ggallagher01 · 2017-05-10T15:51:10Z

Looks good now, white space should be fixed to only what I changed and tests are now passing.

ggallagher01 · 2017-05-29T18:55:59Z

ping @ros/ros_comm-maintainers

All comments I believe are resolved

DLu · 2017-07-07T14:29:15Z

👍

dirk-thomas · 2017-07-10T18:50:44Z

Sorry for the late response. This looks almost ready. Recently some concerns regarding performance came up though which have been addressed in #1091 for the other logging function. Can you please update the PR to use a similar approach. Thank you.

This will also need to be rebased.

…gers under rospy.rosout. This allows for each named logger to have seperate verbosity setting, this will allow for two different verboisty settings for logging in a single node. Two named loggers can log to rosout at two different verbosity setings, which can help noisy debug logs.

dirk-thomas · 2017-07-18T16:50:44Z

Thank you for this new feature. Please consider adding some information to the wiki page to mention this to be available as of Lunar and post the link here for future readers.

kartikmohta · 2017-08-04T01:44:15Z

This breaks the Location of the message shown in rqt_console. Now the location of the message is always shown to be core.py:_base_logger:163 instead of the user code location.

dirk-thomas · 2017-08-11T22:46:48Z

This breaks the Location of the message shown in rqt_console. Now the location of the message is always shown to be core.py:_base_logger:163 instead of the user code location.

@ggallagher01 Can you please look into this.

mikepurvis · 2017-08-11T23:40:14Z

I think the issue here is that we jump up two stack frames in the throttle case, but in the other case we need to jump up one frame (currently nothing):

    if throttle:
         caller_id = _frame_to_caller_id(inspect.currentframe().f_back.f_back)
         _logging_throttle(caller_id, logfunc, throttle, msg, *args)
     else:
         logfunc(msg, *args)

I can verify this and throw up a PR for it.

mikepurvis · 2017-08-14T02:37:40Z

Okay, I did dig into this a little more, and it's not quite as simple— the code I pasted only has to do with identifying the caller for the purposes of enforcing throttling. The actual logic which identifies the caller was added only recently in #1043, see:

https://github.com/ros/ros_comm/blob/lunar-devel/tools/rosgraph/src/rosgraph/roslogging.py#L52-L80

It looks like this is a case where the underlying logic built into logging is basically doing the right thing as far as identifying call site, but since that API has been wrapped, it's now pointing at the wrapper rather than user code. AFAICT, there are a couple ways this could be handled:

Since the amount of wrapping is not always consistent:

Put a blacklist in findCaller (eg, if you see rospy/core.py, keep going, or if you see base_logger, keep going, etc).
In the partial and other pass-thru calls, curry in a number for how many steps out to take.

See some discussion here as well: https://stackoverflow.com/questions/19615876/showing-the-right-funcname-when-wrapping-logger-functionality-in-a-custom-class

mikepurvis · 2017-08-14T03:10:48Z

Okay, I've opened #1141 with a potential fix, so we can discuss that and other options there.

gavanderhoorn · 2017-11-08T10:29:20Z

This is a great addition, but wiki/rospy/Overview/Logging does not mention it. Is that an oversight? @ggallagher01: would you be willing to add that?

From rospy equivalent of ROS_*_NAMED on ROS Answes.

ggallagher31 · 2017-11-09T15:05:08Z

I'll have some time this weekend to add this

yli-cpr · 2018-09-20T21:04:17Z

I found that http://wiki.ros.org/rospy/Overview/Logging doesn't contain the features this commit adds. It may need to be updated.

Another confusing thing is that on the wiki page, rospy.log*() methods don't take kwargs. But it seems before this change, they did accept kwargs.

I am actually looking at the support of exc_info, one of the 2 kwargs that python Logger supports (the other is extra). See https://docs.python.org/2/library/logging.html.

This ticket probably broke the python logger's kwargs like exc_info, because it doesn't forward kwargs to the logger. Should rospy logging support exc_info and extra?

mgrrx · 2018-09-21T20:30:00Z

@yli-cpr checkout #1289 for the support of kwargs.

dirk-thomas · 2018-09-21T23:50:25Z

I'll have some time this weekend to add this

I found that http://wiki.ros.org/rospy/Overview/Logging doesn't contain the features this commit adds. It may need to be updated.

@ggallagher31 Can you please follow up on this and add documentation about this feature to the wiki page.

timonegk · 2019-05-14T21:38:05Z

Ping. This feature is still not documented in the ROS wiki. I would be willing to provide the documentation but the wiki site is immutable for me.

gavanderhoorn · 2019-05-15T07:19:22Z

@timonegk: the wiki is read-only, unless you have an account.

You can register for an account here. After that, you'd have to request write-access (spam protection measure) in ros-infrastructure/roswiki#258.

timonegk · 2019-05-15T09:57:03Z

@gavanderhoorn Thank you. I was not aware of the whitelist.

gavanderhoorn · 2019-05-15T09:58:22Z

I believe it's mentioned after you register.

timonegk · 2019-05-21T18:00:41Z

This feature is now documented (http://wiki.ros.org/rospy/Overview/Logging#Named_Logging).

dirk-thomas reviewed Dec 12, 2016

View reviewed changes

dirk-thomas added the requires-changes label Dec 12, 2016

ggallagher01 force-pushed the rospy_named_loggers branch 2 times, most recently from f251821 to 14f6c53 Compare December 27, 2016 02:20

ggallagher01 force-pushed the rospy_named_loggers branch 2 times, most recently from f7d787a to ab08dff Compare January 10, 2017 19:44

mikepurvis added the hitlist label Jan 11, 2017

ggallagher01 force-pushed the rospy_named_loggers branch from 774d1b7 to a83e09e Compare January 19, 2017 18:08

ggallagher01 force-pushed the rospy_named_loggers branch from a83e09e to e99024f Compare January 26, 2017 21:42

dirk-thomas reviewed Jan 26, 2017

View reviewed changes

mikepurvis added a commit to clearpathrobotics/ros_comm that referenced this pull request Jan 31, 2017

Add named loggers to rospy (ros#948)

1289db2

mikepurvis added a commit that referenced this pull request Jan 31, 2017

Add named loggers to rospy (#948)

f5e04cf

mikepurvis added a commit that referenced this pull request Jan 31, 2017

Add named loggers to rospy (#948)

07114a1

mikepurvis added a commit that referenced this pull request Feb 7, 2017

Add named loggers to rospy (#948)

ef1d794

mikepurvis added a commit that referenced this pull request Feb 7, 2017

Add named loggers to rospy (#948)

066fc94

mikepurvis added a commit that referenced this pull request Feb 7, 2017

Add named loggers to rospy (#948)

061e265

ggallagher01 force-pushed the rospy_named_loggers branch from 9253224 to 1389f4c Compare February 9, 2017 15:22

mikepurvis added a commit that referenced this pull request Feb 9, 2017

Add named loggers to rospy (#948)

cdebc9f

mikepurvis added a commit to clearpathrobotics/ros_comm that referenced this pull request Feb 10, 2017

Add named loggers to rospy (ros#948)

b7bbde3

mikepurvis added a commit that referenced this pull request Feb 10, 2017

Add named loggers to rospy (#948)

0267676

mikepurvis reviewed Feb 16, 2017

View reviewed changes

ggallagher01 force-pushed the rospy_named_loggers branch 2 times, most recently from e0cb90c to 71f587e Compare February 17, 2017 19:38

efernandez pushed a commit to clearpathrobotics/ros_comm that referenced this pull request Feb 23, 2017

Add named loggers to rospy (ros#948)

c6b7cf1

mikepurvis added a commit that referenced this pull request Feb 24, 2017

Add named loggers to rospy (#948)

edda71b

mikepurvis added a commit that referenced this pull request Mar 2, 2017

Add named loggers to rospy (#948)

f7474ac

mikepurvis added a commit that referenced this pull request Mar 28, 2017

Add named loggers to rospy (#948)

1a36ff8

ggallagher01 force-pushed the rospy_named_loggers branch from ce667df to 664666d Compare May 10, 2017 02:10

ggallagher01 force-pushed the rospy_named_loggers branch from 422e9ec to 60e16b3 Compare July 14, 2017 14:08

ggallagher01 force-pushed the rospy_named_loggers branch from 60e16b3 to 58fec5c Compare July 14, 2017 15:37

dirk-thomas removed the requires-changes label Jul 18, 2017

dirk-thomas merged commit 309de11 into ros:lunar-devel Jul 18, 2017

dirk-thomas added the enhancement label Jul 18, 2017

mikepurvis mentioned this pull request Aug 14, 2017

Fix stack frame identification in rospy logging. #1141

Merged

dirk-thomas mentioned this pull request Oct 26, 2017

changes between 1.12.7 and 1.13.4 for backporting #1205

Merged

Add named loggers to rospy #948

Add named loggers to rospy #948

Conversation

ggallagher01 commented Dec 12, 2016

dirk-thomas left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dirk-thomas commented Jan 17, 2017

dirk-thomas left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ggallagher01 commented Feb 9, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ggallagher01 commented Apr 25, 2017

ggallagher01 commented May 10, 2017

ggallagher01 commented May 10, 2017

ggallagher01 commented May 29, 2017

DLu commented Jul 7, 2017

dirk-thomas commented Jul 10, 2017 • edited Loading

dirk-thomas commented Jul 18, 2017

kartikmohta commented Aug 4, 2017

dirk-thomas commented Aug 11, 2017

mikepurvis commented Aug 11, 2017

mikepurvis commented Aug 14, 2017

mikepurvis commented Aug 14, 2017

gavanderhoorn commented Nov 8, 2017 • edited Loading

ggallagher31 commented Nov 9, 2017

yli-cpr commented Sep 20, 2018

mgrrx commented Sep 21, 2018

dirk-thomas commented Sep 21, 2018

timonegk commented May 14, 2019

gavanderhoorn commented May 15, 2019

timonegk commented May 15, 2019

gavanderhoorn commented May 15, 2019

timonegk commented May 21, 2019

ggallagher01 commented Feb 9, 2017 •

edited

Loading

dirk-thomas commented Jul 10, 2017 •

edited

Loading

gavanderhoorn commented Nov 8, 2017 •

edited

Loading