rospy disables standard python logging

[oroulet]

try following:

logging.basicConfig(level=logging.WARN)
logger.warning(1)
print(logger)
rospy.init_node("whaterver")
logger.warning(2)

the second warning does not get printed. It should. rospy is messing with standard python logging. When using third party libraries that relies on logging to print important message to interface this is a big issue.

Rmq: rospy logging works: rospy.logwarn("lkjlkj")

Generally rospy should not change logging from other libraries unless explicitly requested, See there for example for best practices: http://docs.python-guide.org/en/latest/writing/logging/. One might argument that ros is an application and not a library but.....

[oroulet]

I found out I could re-enable logging by adding a root handler:

def fix_logging(level=logging.WARNING):
    console = logging.StreamHandler()
    console.setLevel(level)
    logging.getLogger('').addHandler(console)
    formatter = logging.Formatter('%(levelname)-8s:%(name)-12s: %(message)s')
    console.setFormatter(formatter)
    logging.getLogger('').addHandler(console)

but then rospy logging is printed twice

[warpdriv]

Having this problem too. Found this work around.

https://gist.github.com/nzjrs/8712011

[asimonov]

i have hit this problem too and it took me a while to realise ROS is taking over python logging.
I would say it is a bug, not a feature.
What is the reason to do it this way?

[sjhansen3]

any new info on this?

[sjhansen3]

I was able to get the logger used by ros with the following line:
logging.getLogger('rosout')

Publishing to this logger works just fine, although other loggers are still screwed up because they are not using this namespace. I agree this is an undesirable situation. It would be nice if existing logging would work along side ros code.

[sjhansen3]

I did some more testing and digging

It is not possible to set the logging level for 'rosout' with the following command:

logging.getLogger('rosout').setLevel(logging.DEBUG)

ROS seems to ignore this.

I am however able to add filters on the logging events

[mgrrx]

As outlined here http://wiki.ros.org/rospy/Overview/Logging#Advanced:_Override_Logging_Configuration you can set the environment variable ROS_PYTHON_LOG_CONFIG_FILE and point it to a file which configures python logging for your needs. You can find the default config in $ROS_ETC_DIR/python_logging.conf
rospy.init_node loads this file for you.

[oroulet]

@mgrrx this is irrelevant for that bug isn't it? The point here is that ros breaks everything else logging by default. This is clearly bad practice

[sjhansen3]

I guess, I might be missing something but I would tend to agree with @oroulet. @mgrrx, Could you explain a bit more how we can configure the ROS_PYTHON_LOG_CONFIG_FILE so that other logging handlers will work alongside ros's use of the python logger? Perhaps there is some key architectural reason why this choice was made and we just need to understand it better :)

[ablakey]

I took the workaround shared by @warpdriv and wrapped it to make its usage a bit more obvious: https://gist.github.com/ablakey/4f57dca4ea75ed29c49ff00edf622b38

The result is a one-liner that enables you to selectively re-route specific loggers (and all their children). For example, if I'm debugging Python Requests:

rospy.init_node('explosion_node')
route_logger_to_ros('requests.packages.urllib3')
# And now libraries I import but don't control get their logging re-routed.

Of course a real fix is still important, but this is helping me for now.

[InspireX96]

Found this issue when writing a rostopic monitoring program. After a whole morning of debugging, we found the easiest solution would be reload the logging module after ros_node init:

rospy.init_node('blahblah', anonymous=True)
reload(logging)

Then we can re-handle logging to python

[hd71205991]

Actually rospy just read in a logging config file located in $ROS_ROOT/../../etc/ros/python_logging.conf. It sets the root logger's behavior. I made the normal logging function work without interfering rospylog by adding this:

customlogger = logging.getLogger('__name__')  
fh = logging.FileHandler("/home/username/mylog.log")  
customlogger.setLevel(logging.DEBUG)  
customlogger.addHandler(fh)  
customlogger.debug("This is for debug")  

Remember to call it AFTER the rospy.init_node is called and you are all set. You can add handlers and formatter etc to the logger object and can have the full logging function back.

[dadwin]

another possible approach is to create your logger under rosout logger:
logger = logging.getLogger(f'rosout.{__name__}')

then all subsequent logger's calls will print messages into console, log file and rosout topic.

[130s]

I guess there are 2 different usecases are discussed in this thread so far.

• UC-1. Python library logging not logging/printing (I guess this is what OP reported about).
• UC-2. rospy not including what Python library logging logs (? I may be wrong. But this seems to be what multiple people is complaining about).

I'm blocked by UC-1 not realizing. I tried #1384 (comment), which is to import logging; reload(logging). This seems to improve the situation but not fully; I get tons of error TypeError: unbound method emit() must be called with FileHandler instance as first argument (got RotatingFileHandler instance instead) (and in my case this series of errors isn't great as non-technical users for my application would get alerted unnecessarily).

Output

 Traceback (most recent call last):
   File "/usr/lib/python2.7/logging/handlers.py", line 78, in emit
     logging.FileHandler.emit(self, record)
 TypeError: unbound method emit() must be called with FileHandler instance as first argument (got RotatingFileHandler instance instead)
 Logged from file core.py, line 140
 Traceback (most recent call last):
   File "/usr/lib/python2.7/logging/handlers.py", line 78, in emit
     logging.FileHandler.emit(self, record)
 TypeError: unbound method emit() must be called with FileHandler instance as first argument (got RotatingFileHandler instance instead)
 Logged from file core.py, line 140
 Traceback (most recent call last):
   File "/usr/lib/python2.7/logging/handlers.py", line 78, in emit
     logging.FileHandler.emit(self, record)
 TypeError: unbound method emit() must be called with FileHandler instance as first argument (got RotatingFileHandler instance instead)
 Logged from file core.py, line 140

# apt-cache policy ros-melodic-rospy
ros-melodic-rospy:
  Installed: 1.14.13-1bionic.20220127.143629

[130s]

I made a PR #2243, which is not a solution but offers a way to resolve the issue. I appreciate anyone tries that out and leave feedback, give a review on the PR page.

[viperML]

I can't believe this is still a open issue since 2018

[bhomaidan1990]

@InspireX96 NameError: name 'reload' is not defined, in python>=3.4 solution: importlib.reload(logging)

[Lionelsy]

@InspireX96 NameError: name 'reload' is not defined, in python>=3.4 solution: importlib.reload(logging)

A simple case / solution:
My logger is working again by adding the importlib.reload(logging) after rospy.init_node

rospy.init_node('ros_listener_api', anonymous=True)
importlib.reload(logging)