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

[rospy] Write log for class method with class name for rospy #1043

Merged

Conversation

asmodehn
Copy link
Contributor

@asmodehn asmodehn commented May 2, 2017

#877 Rebased on lunar-devel

wkentaro added 11 commits May 2, 2017 15:29
```
$ export ROSCONSOLE_FORMAT='[${severity}] [${time}]: [${node}] [${function}] ${message}'
```

```
$ python spam.py
[INFO] [1472155704.567361]: [/a] [<module>] a
[WARN] [1472155704.568193]: [/a] [<module>] a
[FATAL] [1472155704.568894]: [/a] [<module>] a
[ERROR] [1472155704.569581]: [/a] [<module>] a
[INFO] [1472155704.570351]: [/a] [main] a
[WARN] [1472155704.571100]: [/a] [main] a
[FATAL] [1472155704.571878]: [/a] [main] a
[ERROR] [1472155704.572626]: [/a] [main] a
[INFO] [1472155704.573439]: [/a] [Test::__init__] a
[WARN] [1472155704.574176]: [/a] [Test::__init__] a
[FATAL] [1472155704.574937]: [/a] [Test::__init__] a
[ERROR] [1472155704.575672]: [/a] [Test::__init__] a
```

```
$ cat spam.py

import rospy

rospy.init_node('a')

rospy.loginfo('a')
rospy.logwarn('a')
rospy.logfatal('a')
rospy.logerr('a')

def main():
    rospy.loginfo('a')
    rospy.logwarn('a')
    rospy.logfatal('a')
    rospy.logerr('a')
main()

class Test(object):
    def __init__(self):
        rospy.loginfo('a')
        rospy.logwarn('a')
        rospy.logfatal('a')
        rospy.logerr('a')
Test()
```
@asmodehn
Copy link
Contributor Author

asmodehn commented May 8, 2017

Not sure why the test failed, no tests are marked as failed, as far as I can see.. any hint ?

@dirk-thomas
Copy link
Member

@asmodehn
Copy link
Contributor Author

asmodehn commented May 8, 2017

Ah thanks, I was digging through the log and didn't pay attention to the main build page...

I can confirm the test behaves as expected, when launched alone, on my local Xenial machine.

It seems that the problem in the test might come from the logging module from the python library.
In Manager.getLogger(), there is this code :

            if name in self.loggerDict:
                rv = self.loggerDict[name]
                if isinstance(rv, PlaceHolder):
                    ph = rv
                    rv = (self.loggerClass or _loggerClass)(name)
                    rv.manager = self
                    self.loggerDict[name] = rv
                    self._fixupChildren(ph, rv)
                    self._fixupParents(rv)
            else:
                rv = (self.loggerClass or _loggerClass)(name)
                rv.manager = self
                self.loggerDict[name] = rv
                self._fixupParents(rv)

So I suspect that when launched with other tests, our current test will fail because the rosout logger is already set and the custom logger class is not used.

Multiple solutions :

  1. Instantiate a Manager in the test, to be used a separate from the default (already used) logging manager. and somehow use that one from 'rosout' logger...
  2. force nose to reinitialize its python interpreter for each tests (or run in isolation somehow)
  3. launch nose tests one by one from CMakeLists.txt (instead on the full test directory)
  4. make a special log for this test to force the custom logger class to be used (using the logging feature that will be wrapped by rospy in Add named loggers to rospy  #948 )

The latter seems the cleaner to me so I ll work on that.

func_name = '%s.%s' % (class_name, func_name)
except KeyError:
pass
return file_name, lineno, func_name
Copy link
Member

Choose a reason for hiding this comment

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

I think it would be good to call the implementation of the base class here and then only "enhance" the function name with additional information.

@dirk-thomas
Copy link
Member

@ros-pull-request-builder retest this please

def findCaller(self):
"""
Find the stack frame of the caller so that we can note the source
file name, line number, and function name with class name if possible.
Copy link
Member

Choose a reason for hiding this comment

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

While this is a good description of the function itself would it be better to document what this specific variation does (extending the function name with the class name if applicable)?

@asmodehn
Copy link
Contributor Author

asmodehn commented May 31, 2017 via email

@wkentaro
Copy link
Contributor

@asmodehn Thank you for addressing this feature. 👍

@dirk-thomas
Copy link
Member

I am sorry for the late response. This looks good. Merging...

@dirk-thomas dirk-thomas merged commit a5c524e into ros:lunar-devel Jul 7, 2017
sputnick1124 pushed a commit to sputnick1124/ros_comm that referenced this pull request Jul 30, 2017
* Write log for class method with class name for rospy

```
$ export ROSCONSOLE_FORMAT='[${severity}] [${time}]: [${node}] [${function}] ${message}'
```

```
$ python spam.py
[INFO] [1472155704.567361]: [/a] [<module>] a
[WARN] [1472155704.568193]: [/a] [<module>] a
[FATAL] [1472155704.568894]: [/a] [<module>] a
[ERROR] [1472155704.569581]: [/a] [<module>] a
[INFO] [1472155704.570351]: [/a] [main] a
[WARN] [1472155704.571100]: [/a] [main] a
[FATAL] [1472155704.571878]: [/a] [main] a
[ERROR] [1472155704.572626]: [/a] [main] a
[INFO] [1472155704.573439]: [/a] [Test::__init__] a
[WARN] [1472155704.574176]: [/a] [Test::__init__] a
[FATAL] [1472155704.574937]: [/a] [Test::__init__] a
[ERROR] [1472155704.575672]: [/a] [Test::__init__] a
```

```
$ cat spam.py

import rospy

rospy.init_node('a')

rospy.loginfo('a')
rospy.logwarn('a')
rospy.logfatal('a')
rospy.logerr('a')

def main():
    rospy.loginfo('a')
    rospy.logwarn('a')
    rospy.logfatal('a')
    rospy.logerr('a')
main()

class Test(object):
    def __init__(self):
        rospy.loginfo('a')
        rospy.logwarn('a')
        rospy.logfatal('a')
        rospy.logerr('a')
Test()
```

* Fix func name {class_name}.{method_name}

* Get line number for rospy logger

* Add test for roslogging ROSCONSOLE_FORMAT

* Add license header

* Don't overwrite logger defined by user

* Inherit user defined custom logger class in RospyLogger

* Fix test name of test_roslogging_user_logger.py

* Make logging test as isolated one

* Revert "Make logging test as isolated one"

This reverts commit 6ac0137.

* Fix test for rosgraph with user custom logger

* using specifically named logger for user logger test.

* [rosgraph] changed logic for roslogging findCaller()
@dirk-thomas
Copy link
Member

@asmodehn Please extend the tests from this PR to also over other logging functions beside loginfo, especially named and throttled loggers. Currently they are partially broken in the latest state, see #1141.

@asmodehn
Copy link
Contributor Author

@dirk-thomas As far as I understand the code :

  • rospy depend on rosgraph
  • rosgraph uses raw python logging (and test the logging format)
  • rospy uses rosgraph logging, and extends it with throttled and named loggers.

So I believe we don't want to extend rosgraph tests to tests throttled and named loggers... We probably want to extend rospy logging tests to verify the logging format in the throttled and named cases instead ?
I ll start working on something like that, see if I get somewhere...

@asmodehn
Copy link
Contributor Author

How about something like that : #1144 ?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants