Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ROS2 Foxy commands are unresponsive #1270

Closed
harun-loodos opened this issue May 18, 2022 · 3 comments
Closed

ROS2 Foxy commands are unresponsive #1270

harun-loodos opened this issue May 18, 2022 · 3 comments
Labels
more-information-needed Further information is required

Comments

@harun-loodos
Copy link

harun-loodos commented May 18, 2022

After both clean Ubuntu and ROS installation, ROS2 commands became unresponsive. Commands are not working and freeze indefinitely on the terminal. Below, you can find the lists for both working and not-working commands and their corresponding outputs if exist.

The commands I can run:

  • ros2 daemon start
    • Failed to confirm that the daemon started successfully
  • ros2 multicast send/receive
    • Sending one UDP multicast datagram... / Waiting for UDP multicast datagram... \n Received from 192.168.0.44:57770: 'Hello World!'
  • ros2 <command> --help commands

The commands I can not run:

  • ros2 topic/action/node/service list
  • ros2 run/launch commands

When I try to run these commands, the process gets unresponsive and I can only force kill the process.

Required Info:

  • Operating System: Ubuntu 20.04.4
  • Installation type: binaries (also tested with source)
    • sudo apt install ros-foxy-desktop
  • Version or commit hash:
    • latest release on debian packages (probably Foxy Path Release 7)
  • DDS implementation:
    • rmw_fastrtps_cpp
  • Client library (if applicable):
    • rclcpp/rclpy

Here I provide a basic example output for
ros2 run demo_nodes_cpp listener --ros-args --log-level DEBUG

The expected behavior is from another system with a working setup. The actual behavior is from the broken system. The process lingers like this indefinitely.

Expected behavior

[DEBUG] [1652866657.694770290] [rclcpp]: signal handler installed
[DEBUG] [1652866657.694828589] [rclcpp]: deferred_signal_handler(): waiting for SIGINT or uninstall
[DEBUG] [1652866657.694833669] [rcl]: Couldn't parse arg 0 (/opt/ros/foxy/lib/demo_nodes_cpp/talker) as a remap rule in its deprecated form. Error: Expected lexeme type (19) not found, search ended at index 39, at /tmp/binarydeb/ros-foxy-rcl-1.1.13/src/rcl/lexer_lookahead.c:233
[DEBUG] [1652866657.694896367] [rcl]: Arg 2 (--log-level) is not a --param nor a -p flag.
[DEBUG] [1652866657.694903711] [rcl]: Arg 2 (--log-level) is not a --remap nor a -r flag.
[DEBUG] [1652866657.694908510] [rcl]: Arg 2 (--log-level) is not a --params-file flag.
[DEBUG] [1652866657.694913579] [rcl]: Got log level: DEBUG

[DEBUG] [1652866657.694942153] [rcl]: Initializing wait set with '0' subscriptions, '2' guard conditions, '0' timers, '0' clients, '0' services
[DEBUG] [1652866657.695159421] [talker]: Load library libtopics_library.so
[DEBUG] [1652866657.697255421] [talker]: Instantiate class rclcpp_components::NodeFactoryTemplate<demo_nodes_cpp::Talker>
[DEBUG] [1652866657.697277443] [rcl]: Couldn't parse arg 0 (/opt/ros/foxy/lib/demo_nodes_cpp/talker) as a remap rule in its deprecated form. Error: Expected lexeme type (19) not found, search ended at index 39, at /tmp/binarydeb/ros-foxy-rcl-1.1.13/src/rcl/lexer_lookahead.c:233
[DEBUG] [1652866657.697286630] [rcl]: Initializing node 'talker' in namespace ''
[DEBUG] [1652866657.697296939] [rcl]: Using domain ID of '0'
[DEBUG] [1652866657.701049392] [rcl]: Initializing publisher for topic name '/rosout'
[DEBUG] [1652866657.701064630] [rcl]: Expanded topic name '/rosout'
[DEBUG] [1652866657.701306224] [rcl]: Publisher initialized
[DEBUG] [1652866657.701317265] [rcl]: Node initialized
[DEBUG] [1652866657.701538200] [rcl]: Initializing service for service name 'talker/get_parameters'
[DEBUG] [1652866657.701544863] [rcl]: Expanded service name '/talker/get_parameters'
[DEBUG] [1652866657.702260258] [rmw_fastrtps_cpp]: ************ Service Details *********
[DEBUG] [1652866657.702268183] [rmw_fastrtps_cpp]: Sub Topic rq/talker/get_parametersRequest
[DEBUG] [1652866657.702270978] [rmw_fastrtps_cpp]: Pub Topic rr/talker/get_parametersReply
[DEBUG] [1652866657.702273563] [rmw_fastrtps_cpp]: ***********
[DEBUG] [1652866657.702375685] [rcl]: Service initialized
[DEBUG] [1652866657.702392476] [rcl]: Initializing service for service name 'talker/get_parameter_types'
[DEBUG] [1652866657.702398097] [rcl]: Expanded service name '/talker/get_parameter_types'
[DEBUG] [1652866657.702421992] [rmw_fastrtps_cpp]: ************ Service Details *********
[DEBUG] [1652866657.702426761] [rmw_fastrtps_cpp]: Sub Topic rq/talker/get_parameter_typesRequest
[DEBUG] [1652866657.702429676] [rmw_fastrtps_cpp]: Pub Topic rr/talker/get_parameter_typesReply
[DEBUG] [1652866657.702434135] [rmw_fastrtps_cpp]: ***********
[DEBUG] [1652866657.702528843] [rcl]: Service initialized
[DEBUG] [1652866657.702539743] [rcl]: Initializing service for service name 'talker/set_parameters'
[DEBUG] [1652866657.702544612] [rcl]: Expanded service name '/talker/set_parameters'
[DEBUG] [1652866657.702570441] [rmw_fastrtps_cpp]: ************ Service Details *********
[DEBUG] [1652866657.702574759] [rmw_fastrtps_cpp]: Sub Topic rq/talker/set_parametersRequest
[DEBUG] [1652866657.702577374] [rmw_fastrtps_cpp]: Pub Topic rr/talker/set_parametersReply
[DEBUG] [1652866657.702581682] [rmw_fastrtps_cpp]: ***********
[DEBUG] [1652866657.702667774] [rcl]: Service initialized
[DEBUG] [1652866657.702678324] [rcl]: Initializing service for service name 'talker/set_parameters_atomically'
[DEBUG] [1652866657.702683614] [rcl]: Expanded service name '/talker/set_parameters_atomically'
[DEBUG] [1652866657.702706487] [rmw_fastrtps_cpp]: ************ Service Details *********
[DEBUG] [1652866657.702710674] [rmw_fastrtps_cpp]: Sub Topic rq/talker/set_parameters_atomicallyRequest
[DEBUG] [1652866657.702715023] [rmw_fastrtps_cpp]: Pub Topic rr/talker/set_parameters_atomicallyReply
[DEBUG] [1652866657.702719271] [rmw_fastrtps_cpp]: ***********
[DEBUG] [1652866657.702829969] [rcl]: Service initialized
[DEBUG] [1652866657.702840589] [rcl]: Initializing service for service name 'talker/describe_parameters'
[DEBUG] [1652866657.702844636] [rcl]: Expanded service name '/talker/describe_parameters'
[DEBUG] [1652866657.702866337] [rmw_fastrtps_cpp]: ************ Service Details *********
[DEBUG] [1652866657.702870836] [rmw_fastrtps_cpp]: Sub Topic rq/talker/describe_parametersRequest
[DEBUG] [1652866657.702873621] [rmw_fastrtps_cpp]: Pub Topic rr/talker/describe_parametersReply
[DEBUG] [1652866657.702877989] [rmw_fastrtps_cpp]: ***********
[DEBUG] [1652866657.702969271] [rcl]: Service initialized
[DEBUG] [1652866657.702979750] [rcl]: Initializing service for service name 'talker/list_parameters'
[DEBUG] [1652866657.702984770] [rcl]: Expanded service name '/talker/list_parameters'
[DEBUG] [1652866657.703008334] [rmw_fastrtps_cpp]: ************ Service Details *********
[DEBUG] [1652866657.703012612] [rmw_fastrtps_cpp]: Sub Topic rq/talker/list_parametersRequest
[DEBUG] [1652866657.703017181] [rmw_fastrtps_cpp]: Pub Topic rr/talker/list_parametersReply
[DEBUG] [1652866657.703021138] [rmw_fastrtps_cpp]: ***********
[DEBUG] [1652866657.703115666] [rcl]: Service initialized
[DEBUG] [1652866657.703129852] [rcl]: Initializing publisher for topic name '/parameter_events'
[DEBUG] [1652866657.703135493] [rcl]: Expanded topic name '/parameter_events'
[DEBUG] [1652866657.703204262] [rcl]: Publisher initialized
[DEBUG] [1652866657.703607290] [rcl]: Finalizing event
[DEBUG] [1652866657.703612961] [rcl]: Event finalized
[DEBUG] [1652866657.703974951] [rcl]: Initializing subscription for topic name '/parameter_events'
[DEBUG] [1652866657.703983237] [rcl]: Expanded topic name '/parameter_events'
[DEBUG] [1652866657.704074117] [rcl]: Subscription initialized
[DEBUG] [1652866657.704183724] [rcl]: Finalizing event
[DEBUG] [1652866657.704188703] [rcl]: Event finalized
[DEBUG] [1652866657.704223699] [rcl]: Initializing publisher for topic name 'chatter'
[DEBUG] [1652866657.704229780] [rcl]: Expanded topic name '/chatter'
[DEBUG] [1652866657.704632637] [rcl]: Publisher initialized
[DEBUG] [1652866657.704658496] [rcl]: Finalizing event
[DEBUG] [1652866657.704662714] [rcl]: Event finalized
[DEBUG] [1652866657.704673384] [rcl]: Initializing timer with period: 1000000000ns
[DEBUG] [1652866657.704702158] [rcl]: Waiting with timeout: 0s + 999976576ns
[DEBUG] [1652866657.704706917] [rcl]: Timeout calculated based on next scheduled timer: true
[DEBUG] [1652866657.704712007] [rcl]: Guard condition in wait set is ready
[DEBUG] [1652866657.704715864] [rcl]: Guard condition in wait set is ready
[DEBUG] [1652866657.704723879] [rcl]: Waiting with timeout: 0s + 999954685ns
[DEBUG] [1652866657.704727876] [rcl]: Timeout calculated based on next scheduled timer: true
[DEBUG] [1652866658.705215068] [rcl]: Timer in wait set is ready
[DEBUG] [1652866658.705294508] [rcl]: Calling timer
[INFO] [1652866658.705321488] [talker]: Publishing: 'Hello World: 1'
[DEBUG] [1652866658.705442325] [rcl]: Waiting with timeout: 0s + 999241318ns
[DEBUG] [1652866658.705451032] [rcl]: Timeout calculated based on next scheduled timer: true
[DEBUG] [1652866658.705463786] [rcl]: Guard condition in wait set is ready
[DEBUG] [1652866658.705473404] [rcl]: Waiting with timeout: 0s + 999210000ns
[DEBUG] [1652866658.705480217] [rcl]: Timeout calculated based on next scheduled timer: true
[DEBUG] [1652866659.705212812] [rcl]: Timer in wait set is ready
[DEBUG] [1652866659.705278595] [rcl]: Calling timer
^C[INFO] [1652866665.024687687] [rclcpp]: signal_handler(signal_value=2)
[DEBUG] [1652866665.024740156] [rclcpp]: signal_handler(): SIGINT received, notifying deferred signal handler
[DEBUG] [1652866665.024792905] [rclcpp]: deferred_signal_handler(): woken up due to SIGINT or uninstall
[DEBUG] [1652866665.024833201] [rclcpp]: deferred_signal_handler(): SIGINT received, shutting down
[DEBUG] [1652866665.024890088] [rclcpp]: deferred_signal_handler(): shutting down rclcpp::Context @ 0x56505420b4e0, because it had shutdown_on_sigint == true
[DEBUG] [1652866665.024904956] [rcl]: Shutting down ROS client library, for context at address: 0x56505420b790
[DEBUG] [1652866665.024948478] [rcl]: Finalizing publisher
[DEBUG] [1652866665.024952195] [rcl]: Guard condition in wait set is ready
[DEBUG] [1652866665.024985708] [rcl]: Timer canceled
[DEBUG] [1652866665.024997149] [rcl]: Timer canceled
[DEBUG] [1652866665.025029229] [rcl]: Finalizing publisher
[DEBUG] [1652866665.025270283] [rcl]: Publisher finalized
[DEBUG] [1652866665.025329614] [rclcpp]: deferred_signal_handler(): waiting for SIGINT or uninstall
[DEBUG] [1652866665.025338290] [rcl]: Publisher finalized
[DEBUG] [1652866665.025363247] [rcl]: Finalizing subscription
[DEBUG] [1652866665.025550018] [rcl]: Subscription finalized
[DEBUG] [1652866665.025568934] [rcl]: Finalizing service
[DEBUG] [1652866665.025691484] [rcl]: Service finalized
[DEBUG] [1652866665.025701183] [rcl]: Finalizing service
[DEBUG] [1652866665.025811500] [rcl]: Service finalized
[DEBUG] [1652866665.025821839] [rcl]: Finalizing service
[DEBUG] [1652866665.025923841] [rcl]: Service finalized
[DEBUG] [1652866665.025933650] [rcl]: Finalizing service
[DEBUG] [1652866665.026031363] [rcl]: Service finalized
[DEBUG] [1652866665.026043166] [rcl]: Finalizing service
[DEBUG] [1652866665.026138775] [rcl]: Service finalized
[DEBUG] [1652866665.026150898] [rcl]: Finalizing service
[DEBUG] [1652866665.026255124] [rcl]: Service finalized
[DEBUG] [1652866665.026264732] [rcl]: Finalizing publisher
[DEBUG] [1652866665.026356264] [rcl]: Publisher finalized
[DEBUG] [1652866665.026384237] [rcl]: Finalizing node
[DEBUG] [1652866665.027784319] [rcl]: Node finalized
[DEBUG] [1652866665.027802793] [rclcpp]: SignalHandler::uninstall(): notifying deferred signal handler
[DEBUG] [1652866665.027834723] [rclcpp]: deferred_signal_handler(): woken up due to SIGINT or uninstall
[DEBUG] [1652866665.027850693] [rclcpp]: deferred_signal_handler(): signal handling uninstalled
[DEBUG] [1652866665.027904244] [rclcpp]: signal handler uninstalled

Actual behavior

[DEBUG] [1652868503.575709883] [rclcpp]: signal handler installed
[DEBUG] [1652868503.575755583] [rcl]: Couldn't parse arg 0 (/opt/ros/foxy/lib/demo_nodes_cpp/listener) as a remap rule in its deprecated form. Error: Expected lexeme type (19) not found, search ended at index 41, at /tmp/binarydeb/ros-foxy-rcl-1.1.13/src/rcl/lexer_lookahead.c:233
[DEBUG] [1652868503.575765843] [rcl]: Arg 2 (--log-level) is not a --param nor a -p flag.
[DEBUG] [1652868503.575769693] [rcl]: Arg 2 (--log-level) is not a --remap nor a -r flag.
[DEBUG] [1652868503.575772833] [rcl]: Arg 2 (--log-level) is not a --params-file flag.
[DEBUG] [1652868503.575776123] [rcl]: Got log level: DEBUG

[DEBUG] [1652868503.575759283] [rclcpp]: deferred_signal_handler(): waiting for SIGINT or uninstall
[DEBUG] [1652868503.575801583] [rcl]: Initializing wait set with '0' subscriptions, '2' guard conditions, '0' timers, '0' clients, '0' services
[DEBUG] [1652868503.575853033] [listener]: Load library libtopics_library.so
[DEBUG] [1652868503.576492361] [listener]: Instantiate class rclcpp_components::NodeFactoryTemplate<demo_nodes_cpp::Listener>
[DEBUG] [1652868503.576514350] [rcl]: Couldn't parse arg 0 (/opt/ros/foxy/lib/demo_nodes_cpp/listener) as a remap rule in its deprecated form. Error: Expected lexeme type (19) not found, search ended at index 41, at /tmp/binarydeb/ros-foxy-rcl-1.1.13/src/rcl/lexer_lookahead.c:233
[DEBUG] [1652868503.576523860] [rcl]: Initializing node 'listener' in namespace ''
[DEBUG] [1652868503.576534450] [rcl]: Using domain ID of '0'
^C[INFO] [1652868642.298481658] [rclcpp]: signal_handler(signal_value=2)
[DEBUG] [1652868642.298516978] [rclcpp]: signal_handler(): SIGINT received, notifying deferred signal handler

Additional information

I tried completely removing any ros related packages and reinstalling from both binaries and source. The results did not change.
There was also Noetic installed and it was working fine. Only Foxy was not working properly.

Edit1: I accidentally post the issue incomplete, then I edited.

@clalancette
Copy link
Contributor

Hm, this is quite a weird one. This seems to be working fine for me, and even seems to be working fine for you in a separate machine.

A few different things to try/check out:

  • Check out your networking setup, and make sure it is configured properly and has multicast enabled. Many ROS 2 commands won't work properly without multicast.
  • Try running some of the ros2 commands with --no-daemon, like: ros2 topic list --no-daemon.
  • Look for hardware errors in dmesg, and/or reboot the machine and try the tests again.
  • Try running this test again on the same machine, but in a docker container. That can at least tell us if something is misconfigured on the host.

@clalancette clalancette added the more-information-needed Further information is required label May 18, 2022
@gavanderhoorn
Copy link

Please note this has a duplicate/related post on ROS Answers: ROS2 (Foxy) commands stopped working.

@tfoote
Copy link
Contributor

tfoote commented May 23, 2022

This looks like a local issue needing debugging more than an issue to track so I'm going to close this in favor of the answers.ros.org post. Please iterate there to get more help finding the issue with this specific machine.

@tfoote tfoote closed this as not planned Won't fix, can't repro, duplicate, stale May 23, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
more-information-needed Further information is required
Projects
None yet
Development

No branches or pull requests

4 participants