[fix] rospy disables non-ROS logging

[130s]

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 after init_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 the rospy node you care about the logging runs on (Ref. wiki.ros.org/rospy/Logging):

      export ROS_PYTHON_LOG_CONFIG_FILE=\`rospack find rosgraph\`/conf/python_logging.yaml

      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

1. Run roscore on another terminal.

   $ docker run --name test_rospy_logger -it ros:noetic-ros-base bash 
   
   source /opt/ros/noetic/setup.bash && roscore

2. 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/

3. On the same terminal,

   export ROS_PYTHON_LOG_CONFIG_FILE=\`rospack find rosgraph\`/conf/python_logging.yaml 

4. 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

[130s]

@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?

[peci1]

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?

[130s]

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.