Fix stack frame identification in rospy logging.

[mikepurvis]

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]

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]

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

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

[dirk-thomas]

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

[mikepurvis]

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

[dirk-thomas]

Better be safe than sorry: 64e284e

[dirk-thomas]

test_roslogging.test_rosconsole__logging_format still fails.

[mikepurvis]

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]

Thank you @mikepurvis. This looks good to go.