Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix stack frame identification in rospy logging. #1141

Merged
merged 5 commits into from
Aug 15, 2017

Conversation

mikepurvis
Copy link
Member

@mikepurvis mikepurvis commented Aug 14, 2017

A possible solution to the issue introduced in #948.

Definitely hacky; should almost certainly be covered by some tests.


Manual verification was by means of the following trivial script:

import rospy

rospy.init_node('test')

r = rospy.Rate(10)
while not rospy.is_shutdown():
   rospy.loginfo('regular logging')
   rospy.loginfo_throttle(0.5, 'throttled logging')
   rospy.loginfo('named logging', logger_name='foobar')
   r.sleep()

Running this, I can rostopic echo /rosout and verify that all the file: fields point to this script name.

However, in the course of playing with this, I noted that the following does not work:

rospy.loginfo('named throttled logging', logger_name='foobar', logger_throttle=0.5)

It crashes on account of the throttle code's assumption that the caller is two stack frames up, whereas in this case it is only one.

FYI @ggallagher01

@mikepurvis
Copy link
Member Author

mikepurvis commented Aug 15, 2017

Okay, so this is I believe in a shippable state as far as unbreaking the head of devel and passing the smoke test laid out in the first post, but it's still not super great. The new deal is:

  • All the logXXX[_YYYY] methods now call _base_logger.
  • Therefore, the "user" method is always two stack frames away from the underlying method.
  • So we can start from the logging-derived one, and jump up two frames, and be good to go.

However, it sucks because:

  • We're now assuming that everything we process is coming through these layers of indirection, which will especially not be the case if we're picking up logging from a third-party module (but isn't even the case internally— there are direct log method calls right in rospy itself, hence the if-checks).

I think it's probably mergeable as-is, but I would propose one or more of the following future directions:

  • Move all these wrapper functions off to their own module.
  • Generate them using some kind of function that can maybe tag or track them somehow.
  • Use that information when walking up the stack, and if no tagged (or logging module) method is found, fall back on the logic from the original class.
  • Eliminate the _base_logger wrapper altogether, and figure out a way to supply throttling/once-ing functionality using the filtering scheme built into to python's logging method.

@dirk-thomas
Copy link
Member

The updated approach looks good to me to get this working and 🚢 again.

I added 8021d9e to fix the log*_once functions.

if f.f_back:
f = f.f_back
if f.f_back:
f = f.f_back
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How about making this "move-two-frames-up" conditional on being "our" use case with the _base_logger?

if f.f_back and f.f_code and f.f_code.co_name == '_base_logger':
    f = f.f_back
    if f.f_back:
        f = f.f_back

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's a better idea. FWIW, I can't really see a case where it would be only one layer of wrapping, so the following should be safe:

if f.f_code and f.f_code.co_name == '_base_logger':
    f = f.f_back.f_back

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Better be safe than sorry: 64e284e

@dirk-thomas
Copy link
Member

test_roslogging.test_rosconsole__logging_format still fails.

@mikepurvis
Copy link
Member Author

Looks like a legit test failure, though. Expected regex was:

INFO on module [0-9]*\\.[0-9]* [0-9]* rosout /tmp/catkin_workspace/src/ros_comm/tools/rosgraph/test/test_roslogging.py [0-9]* <module> /unnamed [0-9]*\\.[0-9]*

Actual was:

INFO on module 1502806685.841191 139998642550528 rosout /usr/lib/python2.7/dist-packages/nose/importer.py 47 Importer.importFromPath /unnamed 1502806685.841208

This is likely to be fixed by 64e284e.

@dirk-thomas
Copy link
Member

Thank you @mikepurvis. This looks good to go.

@dirk-thomas dirk-thomas merged commit dfc4e39 into lunar-devel Aug 15, 2017
@dirk-thomas dirk-thomas deleted the fix-rospy-logging branch August 15, 2017 18:33
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants