Unexpected log file(s) when using mon to launch a file containing python nodes

[dambrosio]

I ran into an interesting observation when using mon to launch a file containing python nodes. It seems as mon directs the logging of the python node into a name file directly inside of the ROS_LOG_DIR directory. This occurs whether or not the --log option is enabled.

Here is the mon command used: mon launch rosmon_py_cpp_logs log.launch --name=rosmon_log --disable-ui --log=/home/dambrosio-dev/.ros/log/latest/rosmon.log

and the directory structure of ROS_LOG_DIR and sub-directory latest:

❯ ls ~/.ros/log
e8616fe4-0447-11ec-a355-803f5d00de5f  latest  py_logger.log

❯ ls latest/
master.log  roslaunch-dambrosio-think-340013.log  rosmon.log  rosout-1-stdout.log  rosout.log

Note: _pylogger.log file in ~/.ros/log

For comparison, here is the directory structure when using roslaunch: roslaunch rosmon_py_cpp_logs log.launch

❯ ls ~/.ros/log
617b626e-0447-11ec-b44a-803f5d00de5f  latest

❯ ls latest/
cpp_logger-1-stdout.log  master.log  py_logger-2-stdout.log  py_logger-2.log  roslaunch-dambrosio-think-338944.log  roslaunch-dambrosio-think-339077.log  rosout-1-stdout.log  rosout.log

For reference, the example package can be used to replicate the above behavior.

Ideally, mon would NOT create a log file for each python node in the root of ROS_LOG_DIR as this can make it difficult to synchronize log files for a given roscore run_id.

I don't believe this is expected behavior, but might be missing something. Appreciate the feedback!

[xqms]

Hi @dambrosio, thanks for the report! This is definitely not intended behavior, but I'm not sure what's causing this.

Could you please gather some more data for me? I'm interested in the command lines and environments of the python node, both under roslaunch and rosmon.

So launch everything using roslaunch / rosmon, find the PID (ps aux | grep py_logger) and then dump the environment and command line:

# Environment
xargs --null --max-args 1 echo < /proc/PID_HERE/environ

# Command line
ps -q PID_HERE auxww

And then we'll try to find a difference :)

[dambrosio]

@xqms thanks for the quick reply. Here is the environment and command line output.

Environment Fyi: The environment variables were sorted and a diff (`diff --unified=0) was performed for readability

diff --git a/xargs-roslaunch-sort.txt b/xargs-monlaunch-sort.txt
index 43921e6..a95b099 100644
--- a/xargs-roslaunch-sort.txt
+++ b/xargs-monlaunch-sort.txt
@@ -16,2 +15,0 @@ NVIDIA_VISIBLE_DEVIDCES=all
-OLDPWD=/home/dambrosio-dev/workspace/autoyard
-_=/opt/ros/kinetic/bin/roslaunch
@@ -27,0 +26 @@ QT_X11_NO_NITSHM=1
+ROSCONSOLE_FORMAT=[${function}]: ${message}
@@ -32 +30,0 @@ ROSLISP_PACKAGE_DIRECTORIES=/home/dambrosio-dev/workspace/autoyard/devel/share/c
-ROS_LOG_FILENAME=/home/dambrosio-dev/.ros/log/ca8ca888-04f8-11ec-9656-803f5d00de5f/roslaunch-dambrosio-think-147977.log

Command line

# roslaunch
dambros+  147997  1.2  0.0 382748 50132 ?        Ssl  16:31   0:00 python /home/dambrosio-dev/workspace/autoyard/src/sbox/rosmon_examples/rosmon_py_cpp_logs/scripts/py_logger __name:=py_logger __log:=/home/dambrosio-dev/.ros/log/ca8ca888-04f8-11ec-9656-803f5d00de5f/py_logger-2.log

# mon
dambros+  147476  0.7  0.0 382748 49936 pts/7    Ssl+ 16:30   0:00 python /home/dambrosio-dev/workspace/autoyard/src/sbox/rosmon_examples/rosmon_py_cpp_logs/scripts/py_logger __name:=py_logger

Looks like the __log node special key is not provided in the mon version. It looks like roslaunch appends __logto the node process in _configure_logging() function (kinetic docs). It puts the node specific log file under log_dir which is a combination of the ROS_HOME/ROS_LOG_DIR environment variable and the ROS run_id (if set).

I was digging through rospy to see if I could find usage of an empty __log key, but had no luck.

[dambrosio]

@xqms anything I can do to help debug this with you?

[xqms]

You are welcome to create a pull request to fix this :)

Otherwise I'll have time to look into it end of September.

[xqms]

Hmm, I finally had time to look into this a bit. The current situation is:

• C++ log messages go into the unified rosmon log file, which is at /tmp/rosmon... or whatever --log specifies.
• Python log messages go to the same file, and additionally into the individual one under $ROS_LOG_DIR.

The question is what the right behavior is... I'm currently developing support for logging to syslog / systemd-journal which is much more capable than both the .ros/log and /tmp/rosmon... solutions. So I'm leaning towards appending __log:=/dev/null to disable any file logging in the nodes themselves.

How does that sound to you?

[xqms]

Since #154 has landed, rosmon (master) behavior should now match what roslaunch is doing. I'll close this now. Feel free to comment again if you still encounter this.