ros_comm
ros_comm copied to clipboard
[fix] rospy disables non-ROS logging
Issue aimed
As reported in https://github.com/ros/ros_comm/issues/1384#issue-319859166, logs that are logged by Python's logging
stops printing after rospy.init_node
call, which shouldn't happen IMO (i.e. non-rospy
loggers should be able to keep logging separately from rospy
loggers).
Solution approach
- Configure
rospy
so that it does NOT disable existing loggers (even afterinit_node
is called).- Implementation: In this PR, a new config file that stops disabling existing loggers.
- Conf file that's been used is replaced by a new, YAML formated file, which is the only format AFAIK with Python's
logging
module that lets us achieve what I want. - Conf file must be somehow passed to the running
rosgraph
at the time of writing (2022/05/17) by the human operator. It can be done e.g. by setting env var by the following command on the BASH terminal where therospy
node you care about the logging runs on (Ref. wiki.ros.org/rospy/Logging):
- Conf file that's been used is replaced by a new, YAML formated file, which is the only format AFAIK with Python's
- Implementation: In this PR, a new config file that stops disabling existing loggers.
Open questions.
- I reached to this solution by rather an empirical approach without exploring other, potentially better approaches (though I already spent a lot of time in reaching this PR).
- Regarding backward compatibility:
- Logging output format changed "a little bit". Unless there's usecase that scans the text output, this shouldn't be a breaker IMO.
-
.conf
file is replaced with.yaml
for the reason said above.
- The change in this PR as of writing does NOT automatically solve the issue. Instead, there's still a user's operation needed, as mentioned in the solution approach section. I leave like this because I haven't thought of a way that works in all potential
rospy
usecases.- If reviewers give ideas then I can try implementing that. If maintainers thinks the current approach is good enough, that's fine too.
- I thought of setting the environment variable when build occurs (e.g.
cmake
via Catkin). I'm just not so sure just yet if that implementation is good to configure runtime environment.
- No test case added as of writing. Ran out of time. If test is a strong requirement I should be able to dedicate some more time, but first I want to know if the solution approach is acceptable.
- Why targeting
melodic
branch? Good question. I can easily open another PR for newer branches if requested. At least we should be able to continue discussion on this PR.
Manual test steps and result
- Run
roscore
on another terminal.$ docker run --name test_rospy_logger -it ros:noetic-ros-base bash source /opt/ros/noetic/setup.bash && roscore
- Build
rosgraph
pkg with this change on another bash terminal.$ docker exec -it test_rospy_logger bash mkdir -p /cws/src && cd /cws/src git clone https://github.com/130s/ros_comm -b fix-1384-py-logging-melodic cd /cws && source /opt/ros/noetic/setup.bash catkin config --install && catkin build --no-deps rosgraph -DCMAKE_INSTALL_PREFIX=/opt/ros/noetic/
- On the same terminal,
export ROS_PYTHON_LOG_CONFIG_FILE=\`rospack find rosgraph\`/conf/python_logging.yaml
- Run the test code. I ran
ipython3
, and copy-pasted the test code.Test code
import logging import rospy LOGGERNAME = "my-logger" #logging.basicConfig(level=logging.WARN) logger = logging.getLogger(LOGGERNAME) logger.warning("log-1: Do not forget to run roscore on another terminal") print(logger) rospy.loginfo("2: Since node is not initialized, this shouldn't be printed") rospy.init_node("whaterver") logger.warning(3) rospy.loginfo(4) logger = logging.getLogger(LOGGERNAME) logger.warning(5) logger.warning("genlog-6") rospy.loginfo("roslog-7")
Test result
Without the change in this PR:
log-1: Do not forget to run roscore on another terminal
<RospyLogger my-logger (WARNING)>
[INFO] [1652736517.520778]: 4
[INFO] [1652736517.525223]: roslog-7
With the change in this PR. You see all the logging sequence from 1 (except sequence-2 that is meant to be NOT printed):
:
log-1: Do not forget to run roscore on another terminal
<RospyLogger my-logger (WARNING)>
[rospy.client][INFO] 2022-05-16 21:28:06,497: init_node, name[/whaterver], pid[8679]
[xmlrpc][INFO] 2022-05-16 21:28:06,497: XML-RPC server binding to 0.0.0.0:0
[xmlrpc][INFO] 2022-05-16 21:28:06,497: Started XML-RPC server [http://4a33e0109f61:42217/]
[rospy.init][INFO] 2022-05-16 21:28:06,498: ROS Slave URI: [http://4a33e0109f61:42217/]
[rospy.impl.masterslave][INFO] 2022-05-16 21:28:06,498: _ready: http://4a33e0109f61:42217/
[rospy.registration][INFO] 2022-05-16 21:28:06,499: Registering with master node http://localhost:11311
[xmlrpc][INFO] 2022-05-16 21:28:06,499: xml rpc node: starting XML-RPC server
[rospy.init][INFO] 2022-05-16 21:28:06,598: registered with master
[rospy.rosout][INFO] 2022-05-16 21:28:06,599: initializing /rosout core topic
[rospy.rosout][INFO] 2022-05-16 21:28:06,607: connected to core topic /rosout
[rospy.simtime][INFO] 2022-05-16 21:28:06,609: /use_sim_time is not set, will not subscribe to simulated time [/clock] topic
[my-logger][WARNING] 2022-05-16 21:28:06,615: 3
[rosout][INFO] 2022-05-16 21:28:06,615: 4
[my-logger][WARNING] 2022-05-16 21:28:06,619: 5
[my-logger][WARNING] 2022-05-16 21:28:06,619: genlog-6
[rosout][INFO] 2022-05-16 21:28:06,620: roslog-7
@asmodehn Would you mind reviewing as you worked on https://github.com/ros/ros_comm/issues/1029 where support for Py logging conf was enhanced?
I think changing the logging format and the name of the installed conf file are not acceptable changes for released ROS distros. Could you look for alternatives?
I think changing the logging format and the name of the installed conf file are not acceptable changes for released ROS distros. Could you look for alternatives?
That's fair. The current state of this PR changes the format so I agree it'd be frowned upon by existing users. That said, we should be able to customize the format in the same approach taken in this PR. I just haven't tried yet.