search

ros2 / ros2cli

ROS 2 command line interface tools
Apache License 2.0
173 stars 159 forks source link

Log file is exclusively named after process name in both `rclpy` and `rclcpp` #856

Closed sea-bass closed 7 months ago

sea-bass commented 11 months ago

Bug report

Required Info:

Steps to reproduce issue

When I run the following command:

ros2 run demo_nodes_py talker --ros-args -r __node:=my_talker

Expected behavior

I would expect looking into my ROS logs folder, e.g., ~/.ros/log and seeing a log file named after the node (my_talker).

e.g. my_talker_96363_1695751593253.log

Actual behavior

However, I am instead seeing a generic Python name: python3_96363_1695751593253.log

This makes it very inconvenient to search for logs by node name, which should be the case.

Additional information

Running ros2 node list shows this node name correctly; it's just the logger that is wrong:

$ ros2 node list
/my_talker

Additionally, this also happens with rclcpp based nodes but in a different way.

For example

ros2 run demo_nodes_cpp talker --ros-args -r __node:=my_talker

yields the following log file name:

talker_96405_1695751970731.log

... which is the default node name, but this should be as follows, right?

my_talker_96405_1695751970731.log

Feature request

The node name should actually be used in the log file names created from rclpy nodes, as described in the "Expected Behavior" section above.

fujitatomoya commented 11 months ago

ROS 2 can have multiple nodes in the same process space, so node name would not be suitable for log file name.

current implementation uses program name for the log file name,

https://github.com/ros2/rcl_logging/blob/014239dd80ab3de2a847af80f23d24da6438ecb7/rcl_logging_spdlog/src/rcl_logging_spdlog.cpp#L156

and,

https://github.com/ros2/rcutils/blob/f078c8c94885c94809d5d185822cf8ae8d4b795f/include/rcutils/process.h#L55

i think using program name is fine (rclcpp case) but once it comes to python, it returns python3.

something we can do is replace program name with argv[1]: script name? any thoughts?

sea-bass commented 11 months ago

I see -- thank you! So each file is specific to a process? In that case, I think using the script name could work as a first pass.

Ideally, there would also be a way to configure the logger name in ros2 run / ros2 launch as well, though?

fujitatomoya commented 11 months ago

allowing user application to set the log file name sounds reasonable for me. user application can set the unique identification to the log file that is easy to search the log file. (e.g environmental variable, ros2cli command line option.)

there would also be a way to configure the logger name in ros2 run / ros2 launch as well, though?

i am not sure if that option is available for launch. probably not, since underlying implementation does not seem to support that feature yet. you can open the discussion for https://github.com/ros2/launch_ros.

MichaelOrlov commented 10 months ago

@fujitatomoya As regards

something we can do is replace program name with argv[1]: script name? any thoughts?

Could you please clarify what you mean by that or in what place we could potentially do this?

MichaelOrlov commented 10 months ago

I would consider adding one extra parameter *const char program_name** to the 

rcl_logging_ret_t
rcl_logging_external_initialize(const char * program_name, const char * config_file, rcutils_allocator_t allocator);

and to the 

rcl_ret_t
rcl_logging_configure_with_output_handler(
  const char * program_name,
  const rcl_arguments_t * global_args,
  const rcl_allocator_t * allocator,
  rcl_logging_output_handler_t output_handler)

To be able to provide program_name explicitly from the upper layer. It could be null_ptr by default and we can fallback to the rcutils_get_executable_name(..) call if it is null_ptr as we currently do.

fujitatomoya commented 10 months ago

Could you please clarify what you mean by that or in what place we could potentially do this?

root         388     385  3 20:20 pts/2    00:00:01 /usr/bin/python3 /root/ros2_ws/colcon_ws/install/demo_nodes_py/lib/demo_nodes_py/talker
MichaelOrlov commented 10 months ago

@fujitatomoya Sorry still didn't get how you replaced the program name with argv[1] ? How to do this with ros2cli API and extensions?

fujitatomoya commented 10 months ago

@MichaelOrlov oh, that is just an idea to replace python3 with python script name(argv[1]) via rcutils_get_executable_name if that is python3, so we cannot do that now. i do not think this is an good idea either, so i was thinking probably we can use global argument as well.

iuhilnehc-ynos commented 10 months ago

another alternative solution, thoughts?

src/logging.c

    static char g_rcutils_logging_custom_executable_name[RCUTILS_FILENAME_LEN];

    rcutils_ret_t rcutils_logging_set_executable_name(const char *, bool force);

    char * rcutils_logging_get_executable_name();
        get g_rcutils_logging_custom_executable_name
        check g_rcutils_logging_custom_executable_name if it's necessary to call `rcutils_get_executable_name`
    rclpy/rclpy/src/rclpy/logging.cpp

    logging_configure
        to call rcutils_logging_set_executable_name(basename) before `rcl_logging_configure_with_output_handler`

        // to set the executable name
        try
        {
            py::module main_module = py::module::import("__main__");
            std::string file_name = main_module.attr("__file__").cast<std::string>();
            printf("file name:%s\n", fs::path(file_name).filename().c_str());
            // to call `rcutils_logging_set_executable_name(name, false)`
            // NOTE: ros2cli command can set the name before, and global_arguments can force updating it later
        }
        catch (const std::exception& ex)
        {
            RCUTILS_SAFE_FWRITE_TO_STDERR("rclpy failed to get the script file name");
            RCUTILS_SAFE_FWRITE_TO_STDERR(ex.what());
            RCUTILS_SAFE_FWRITE_TO_STDERR("\n");
        }
fujitatomoya commented 8 months ago

@sea-bass could you try,

it works in my local environment.

root@tomoyafujita:~/ros2_ws/colcon_ws# ros2 run demo_nodes_py talker --ros-args --log-file-name foobar
[INFO] [1702509980.781646208] [talker]: Publishing: "Hello World: 0"
...
root@tomoyafujita:~/.ros/log# ls -lt
total 328
-rw-r--r-- 1 root root    0 Dec 13 15:26  foobar_585207_1702509979643.log
sea-bass commented 8 months ago

@sea-bass could you try,

it works in my local environment.

root@tomoyafujita:~/ros2_ws/colcon_ws# ros2 run demo_nodes_py talker --ros-args --log-file-name foobar
[INFO] [1702509980.781646208] [talker]: Publishing: "Hello World: 0"
...
root@tomoyafujita:~/.ros/log# ls -lt
total 328
-rw-r--r-- 1 root root    0 Dec 13 15:26  foobar_585207_1702509979643.log

This is great -- thank you for the update!

Would the path forward to specify this from launch files to similarly add to the ROS args using the existing launch APIs?

fujitatomoya commented 8 months ago

@sea-bass

Would the path forward to specify this from launch files to similarly add to the ROS args using the existing launch APIs?

yeah, it should be, that was the intention. along with other arguments such as --log-level.

i think we need to add those test cases for launch and ros2cli, see https://github.com/ros2/rcl/pull/1127#discussion_r1425992174

fujitatomoya commented 8 months ago

@clalancette i got a few follow-up PRs to close this issue. could you review these?

ros-discourse commented 3 months ago

This issue has been mentioned on ROS Discourse. There might be relevant details there:

https://discourse.ros.org/t/ros-2-jazzy-jalisco-released/37862/1