Fix override command timeouts #110

andermi · 2022-11-30T21:26:29Z

Sending commands mid-override did not extend timeout.

Discovered when testing osrf/mbari_wec_utils#37

Signed-off-by: Michael Anderson <[email protected]>

hamilton8415 · 2022-11-30T21:51:56Z

Working nicely now, providing quite realistic behaviors compared to the real system (running with the tweak branch of buoy_msgs of course). I was able to get pc_WindCurr to crash however, output below. I was issuing the command over and over and eventually this happened. So I was probably hitting return on the next command before the first returned. I'm fast, years of centipede in the arcade... :)

I was able to recreate, and it doesn't spit the Traceback and all of that until I ctrl-c'd after it hung on the "^[[A" output. Takes down the simulator as well...

Possibly related, I am working on my office linux machine over a questionable remote desktop link, so it doesn't feel like a great typing experience in the best of times...

hamilton@wolfpack:~/buoy_ws$ ~/.local/bin/pc_WindCurr -5
Executing pc_WindCurr to Set the winding current target for Power Controller: -5.0
^[[A


^CTraceback (most recent call last):
  File "/home/hamilton/.local/bin/pc_WindCurr", line 11, in <module>
    load_entry_point('pbcmd==0.0.0', 'console_scripts', 'pbcmd')()
  File "/home/hamilton/buoy_ws/install/pbcmd/lib/python3.8/site-packages/pbcmd/pbcmd.py", line 237, in main
    cmds[parser.prog](parser)
  File "/home/hamilton/buoy_ws/install/pbcmd/lib/python3.8/site-packages/pbcmd/pbcmd.py", line 208, in pc_WindCurr
    _pbcmd.send_pc_wind_curr_command(args.wind_curr)
  File "/home/hamilton/buoy_ws/install/buoy_api_py/lib/python3.8/site-packages/buoy_api/interface.py", line 287, in send_pc_wind_curr_command
    return asyncio.run(self._send_pc_wind_curr_command(wind_curr, blocking))
  File "/usr/lib/python3.8/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.8/asyncio/base_events.py", line 603, in run_until_complete
    self.run_forever()
  File "/usr/lib/python3.8/asyncio/base_events.py", line 570, in run_forever
    self._run_once()
  File "/usr/lib/python3.8/asyncio/base_events.py", line 1823, in _run_once
    event_list = self._selector.select(timeout)
  File "/usr/lib/python3.8/selectors.py", line 464, in select
    max_ev = max(len(self._fd_to_key), 1)
KeyboardInterrupt

hamilton8415 · 2022-11-30T21:55:40Z

Looks like 8-bit assembly language programming. Not bad.
https://en.wikipedia.org/wiki/Centipede_(video_game)

andermi · 2022-11-30T22:05:59Z

get pc_WindCurr to crash

I suspect the crash was on the simulator end and hung the service call awaiting a response on the pbcmd side. Do you have output from the sim?

andermi · 2022-11-30T22:16:06Z

I love Centipede, too :) I'm also a big fan of Ambrosia Software's now obsolete "modernization": https://en.wikipedia.org/wiki/Apeiron_(video_game)

hamilton8415 · 2022-11-30T22:19:35Z

Oh yes, of course. I didn't look at that, it was behind a bunch of windows... Pasted below, you can see the WindCurr over-rides followed by trouble...

[ign gazebo-1] [INFO] [1669844930.786311505] [power_controller]: Continue Override Winding Current (Torque) (9.506s)
[ign gazebo-1] [INFO] [1669844931.241362445] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [-5 Amps]
[ign gazebo-1] [INFO] [1669844931.241601907] [power_controller]: Continue Override Winding Current (Torque) (9.927s)
[ign gazebo-1] [INFO] [1669844931.655020514] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [-5 Amps]
[ign gazebo-1] [INFO] [1669844931.655737093] [power_controller]: Continue Override Winding Current (Torque) (10.315s)
[ign gazebo-1] terminate called after throwing an instance of 'rclcpp::exceptions::RCLError'
[ign gazebo-1]   what():  failed to send response: cannot publish data, at /tmp/binarydeb/ros-galactic-rmw-cyclonedds-cpp-0.22.5/src/rmw_node.cpp:4041, at /tmp/binarydeb/ros-galactic-rcl-3.1.3/src/rcl/service.c:287
[ign gazebo-1] Stack trace (most recent call last) in thread 3413184:
[ign gazebo-1] #24   Object "[0xffffffffffffffff]", at 0xffffffffffffffff, in 
[ign gazebo-1] #23   Object "/lib/x86_64-linux-gnu/libc.so.6", at 0x7ff5b4a1f132, in clone
[ign gazebo-1] #22   Object "/lib/x86_64-linux-gnu/libpthread.so.0", at 0x7ff5b48e5608, in 
[ign gazebo-1] #21   Object "/lib/x86_64-linux-gnu/libstdc++.so.6", at 0x7ff5b0a7fde3, in 
[ign gazebo-1] #20   Object "/home/hamilton/buoy_ws/install/buoy_gazebo/lib/libPowerController.so", at 0x7ff58c332a11, in std::thread::_State_impl<std::thread::_Invoker<std::tuple<buoy_gazebo::PowerControllerPrivate::ros2_setup(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)::{lambda()#2}> > >::_M_run()
[ign gazebo-1] #19   Object "/home/hamilton/buoy_ws/install/buoy_gazebo/lib/libPowerController.so", at 0x7ff58c334d01, in std::thread::_Invoker<std::tuple<buoy_gazebo::PowerControllerPrivate::ros2_setup(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)::{lambda()#2}> >::operator()()
[ign gazebo-1] #18   Object "/home/hamilton/buoy_ws/install/buoy_gazebo/lib/libPowerController.so", at 0x7ff58c33714f, in void std::thread::_Invoker<std::tuple<buoy_gazebo::PowerControllerPrivate::ros2_setup(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)::{lambda()#2}> >::_M_invoke<0ul>(std::_Index_tuple<0ul>)
[ign gazebo-1] #17   Object "/home/hamilton/buoy_ws/install/buoy_gazebo/lib/libPowerController.so", at 0x7ff58c33842f, in std::__invoke_result<buoy_gazebo::PowerControllerPrivate::ros2_setup(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)::{lambda()#2}>::type std::__invoke<buoy_gazebo::PowerControllerPrivate::ros2_setup(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)::{lambda()#2}>(std::__invoke_result&&, (buoy_gazebo::PowerControllerPrivate::ros2_setup(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)::{lambda()#2}&&)...)
[ign gazebo-1] #16   Object "/home/hamilton/buoy_ws/install/buoy_gazebo/lib/libPowerController.so", at 0x7ff58c338be1, in void std::__invoke_impl<void, buoy_gazebo::PowerControllerPrivate::ros2_setup(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)::{lambda()#2}>(std::__invoke_other, buoy_gazebo::PowerControllerPrivate::ros2_setup(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)::{lambda()#2}&&)
[ign gazebo-1] #15   Object "/home/hamilton/buoy_ws/install/buoy_gazebo/lib/libPowerController.so", at 0x7ff58c2c82cc, in buoy_gazebo::PowerControllerPrivate::ros2_setup(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)::{lambda()#2}::operator()() const
[ign gazebo-1] #14   Object "/opt/ros/galactic/lib/librclcpp.so", at 0x7ff5943151a6, in rclcpp::Executor::spin_once(std::chrono::duration<long, std::ratio<1l, 1000000000l> >)
[ign gazebo-1] #13   Object "/opt/ros/galactic/lib/librclcpp.so", at 0x7ff59431da70, in rclcpp::Executor::spin_once_impl(std::chrono::duration<long, std::ratio<1l, 1000000000l> >)
[ign gazebo-1] #12   Object "/opt/ros/galactic/lib/librclcpp.so", at 0x7ff5943190ac, in rclcpp::Executor::execute_any_executable(rclcpp::AnyExecutable&)
[ign gazebo-1] #11   Object "/opt/ros/galactic/lib/librclcpp.so", at 0x7ff59431828b, in rclcpp::Executor::execute_service(std::shared_ptr<rclcpp::ServiceBase>)
[ign gazebo-1] #10   Object "/opt/ros/galactic/lib/librclcpp.so", at 0x7ff594318013, in 
[ign gazebo-1] #9    Object "/opt/ros/galactic/lib/librclcpp.so", at 0x7ff59431766c, in 
[ign gazebo-1] #8    Object "/home/hamilton/buoy_ws/install/buoy_gazebo/lib/libPowerController.so", at 0x7ff58c33389b, in rclcpp::Service<buoy_interfaces::srv::PCWindCurrCommand>::handle_request(std::shared_ptr<rmw_request_id_t>, std::shared_ptr<void>)
[ign gazebo-1] #7    Object "/home/hamilton/buoy_ws/install/buoy_gazebo/lib/libPowerController.so", at 0x7ff58c3360e7, in rclcpp::Service<buoy_interfaces::srv::PCWindCurrCommand>::send_response(rmw_request_id_t&, buoy_interfaces::srv::PCWindCurrCommand_Response_<std::allocator<void> >&)
[ign gazebo-1] #6    Object "/opt/ros/galactic/lib/librclcpp.so", at 0x7ff594312b5c, in rclcpp::exceptions::throw_from_rcl_error(int, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, rcutils_error_state_t const*, void (*)())
[ign gazebo-1] #5    Object "/lib/x86_64-linux-gnu/libstdc++.so.6", at 0x7ff5b0a5337e, in std::rethrow_exception(std::__exception_ptr::exception_ptr)
[ign gazebo-1] #4    Object "/lib/x86_64-linux-gnu/libstdc++.so.6", at 0x7ff5b0a533f6, in std::terminate()
[ign gazebo-1] #3    Object "/lib/x86_64-linux-gnu/libstdc++.so.6", at 0x7ff5b0a5338b, in 
[ign gazebo-1] #2    Object "/lib/x86_64-linux-gnu/libstdc++.so.6", at 0x7ff5b0a47910, in 
[ign gazebo-1] #1    Object "/lib/x86_64-linux-gnu/libc.so.6", at 0x7ff5b4922858, in abort
[ign gazebo-1] #0    Object "/lib/x86_64-linux-gnu/libc.so.6", at 0x7ff5b494300b, in gsignal
[ign gazebo-1] Aborted (Signal sent by tkill() 3413063 685)
[INFO] [ign gazebo-1]: process has finished cleanly [pid 3413030]
^C[WARNING] [launch]: user interrupted with ctrl-c (SIGINT)
[parameter_bridge-2] [INFO] [1669844965.179183866] [rclcpp]: signal_handler(signal_value=2)
^C[WARNING] [launch]: user interrupted with ctrl-c (SIGINT) again, ignoring...
[INFO] [parameter_bridge-2]: process has finished cleanly [pid 3413033]
hamilton@wolfpack:~/buoy_ws$ ^C
hamilton@wolfpack:~/buoy_ws$ ^C
hamilton@wolfpack:~/buoy_ws$ ^C

hamilton8415 · 2022-11-30T22:28:50Z

Looking at the previous current-command time-stamps, the one that failed was the fastest iteration I can find, at 414ms, FWIW.

[ign gazebo-1] [INFO] [1669844903.085650396] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844903.087647561] [power_controller]: Override Winding Current (Torque) (2s)
[ign gazebo-1] [INFO] [1669844905.198360489] [power_controller]: Stopped overriding Winding Current (Torque) after (2s)
[ign gazebo-1] [INFO] [1669844906.640676578] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844906.642098703] [power_controller]: Override Winding Current (Torque) (2s)
[ign gazebo-1] [INFO] [1669844907.270169712] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844907.270972456] [power_controller]: Continue Override Winding Current (Torque) (2.591s)
[ign gazebo-1] [INFO] [1669844907.877165010] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844907.877414072] [power_controller]: Continue Override Winding Current (Torque) (3.164s)
[ign gazebo-1] [INFO] [1669844908.483808927] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844908.484694685] [power_controller]: Continue Override Winding Current (Torque) (3.735s)
[ign gazebo-1] [INFO] [1669844909.047011766] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844909.047258522] [power_controller]: Continue Override Winding Current (Torque) (4.263s)
[ign gazebo-1] [INFO] [1669844909.556869542] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844909.557279259] [power_controller]: Continue Override Winding Current (Torque) (4.743s)
[ign gazebo-1] [INFO] [1669844910.036793767] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844910.037323650] [power_controller]: Continue Override Winding Current (Torque) (5.198s)
[ign gazebo-1] [INFO] [1669844910.352749871] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844910.353037680] [power_controller]: Continue Override Winding Current (Torque) (5.492s)
[ign gazebo-1] [INFO] [1669844910.754192481] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844910.754664228] [power_controller]: Continue Override Winding Current (Torque) (5.873s)
[ign gazebo-1] [INFO] [1669844911.128522491] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844911.129378057] [power_controller]: Continue Override Winding Current (Torque) (6.227s)
[ign gazebo-1] [INFO] [1669844911.447540721] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844911.447688984] [power_controller]: Continue Override Winding Current (Torque) (6.523s)
[ign gazebo-1] [INFO] [1669844911.812272252] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844911.812447984] [power_controller]: Continue Override Winding Current (Torque) (6.866s)
[ign gazebo-1] [INFO] [1669844912.152422085] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844912.153129117] [power_controller]: Continue Override Winding Current (Torque) (7.182s)
[ign gazebo-1] [INFO] [1669844912.453134736] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844912.453379565] [power_controller]: Continue Override Winding Current (Torque) (7.463s)
[ign gazebo-1] [INFO] [1669844912.781177508] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844912.781896149] [power_controller]: Continue Override Winding Current (Torque) (7.77s)
[ign gazebo-1] [INFO] [1669844913.115788177] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844913.116036078] [power_controller]: Continue Override Winding Current (Torque) (8.086s)
[ign gazebo-1] [INFO] [1669844913.499429450] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844913.499959010] [power_controller]: Continue Override Winding Current (Torque) (8.451s)
[ign gazebo-1] [INFO] [1669844913.865841562] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844913.865912864] [power_controller]: Continue Override Winding Current (Torque) (8.796s)
[ign gazebo-1] [INFO] [1669844914.220831078] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844914.220931685] [power_controller]: Continue Override Winding Current (Torque) (9.133s)
[ign gazebo-1] [INFO] [1669844914.557827128] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844914.558659685] [power_controller]: Continue Override Winding Current (Torque) (9.448s)
[ign gazebo-1] [INFO] [1669844914.919899549] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844914.920226505] [power_controller]: Continue Override Winding Current (Torque) (9.783s)
[ign gazebo-1] [INFO] [1669844915.235946625] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844915.236055256] [power_controller]: Continue Override Winding Current (Torque) (10.083s)
[ign gazebo-1] [INFO] [1669844915.608521248] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844915.608814900] [power_controller]: Continue Override Winding Current (Torque) (10.438s)
[ign gazebo-1] [INFO] [1669844916.015607390] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844916.016160307] [power_controller]: Continue Override Winding Current (Torque) (10.821s)
[ign gazebo-1] [INFO] [1669844916.235036336] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844916.235366108] [power_controller]: Continue Override Winding Current (Torque) (11.03s)
[ign gazebo-1] [INFO] [1669844916.558726061] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844916.559383975] [power_controller]: Continue Override Winding Current (Torque) (11.338s)
[ign gazebo-1] [INFO] [1669844916.813730694] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844916.813852727] [power_controller]: Continue Override Winding Current (Torque) (11.58s)
[ign gazebo-1] [INFO] [1669844917.166857516] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844917.166967077] [power_controller]: Continue Override Winding Current (Torque) (11.915s)
[ign gazebo-1] [INFO] [1669844917.498384280] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844917.498581364] [power_controller]: Continue Override Winding Current (Torque) (12.229s)
[ign gazebo-1] [INFO] [1669844917.841971869] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844917.842551860] [power_controller]: Continue Override Winding Current (Torque) (12.558s)
[ign gazebo-1] [INFO] [1669844918.228571652] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844918.229482231] [power_controller]: Continue Override Winding Current (Torque) (12.926s)
[ign gazebo-1] [INFO] [1669844918.538761168] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844918.539467466] [power_controller]: Continue Override Winding Current (Torque) (13.219s)
[ign gazebo-1] [INFO] [1669844918.980131673] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844918.980684035] [power_controller]: Continue Override Winding Current (Torque) (13.637s)
[ign gazebo-1] [INFO] [1669844919.581039526] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844919.581917979] [power_controller]: Continue Override Winding Current (Torque) (14.212s)
[ign gazebo-1] [INFO] [1669844921.670158683] [power_controller]: Stopped overriding Winding Current (Torque) after (14.212s)
[ign gazebo-1] [INFO] [1669844922.818802405] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844922.820089825] [power_controller]: Override Winding Current (Torque) (2s)
[ign gazebo-1] [INFO] [1669844923.626984803] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844923.627773299] [power_controller]: Continue Override Winding Current (Torque) (2.769s)
[ign gazebo-1] [INFO] [1669844924.256337933] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844924.257156047] [power_controller]: Continue Override Winding Current (Torque) (3.358s)
[ign gazebo-1] [INFO] [1669844924.873426872] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844924.873600901] [power_controller]: Continue Override Winding Current (Torque) (3.935s)
[ign gazebo-1] [INFO] [1669844926.254179843] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [5 Amps]
[ign gazebo-1] [INFO] [1669844926.254969307] [power_controller]: Continue Override Winding Current (Torque) (5.245s)
[ign gazebo-1] [INFO] [1669844927.165340222] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [-5 Amps]
[ign gazebo-1] [INFO] [1669844927.165447101] [power_controller]: Continue Override Winding Current (Torque) (6.115s)
[ign gazebo-1] [INFO] [1669844927.768359461] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [-5 Amps]
[ign gazebo-1] [INFO] [1669844927.768835021] [power_controller]: Continue Override Winding Current (Torque) (6.675s)
[ign gazebo-1] [INFO] [1669844928.281817584] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [-5 Amps]
[ign gazebo-1] [INFO] [1669844928.282784409] [power_controller]: Continue Override Winding Current (Torque) (7.162s)
[ign gazebo-1] [INFO] [1669844928.818387890] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [-5 Amps]
[ign gazebo-1] [INFO] [1669844928.818581467] [power_controller]: Continue Override Winding Current (Torque) (7.666s)
[ign gazebo-1] [INFO] [1669844929.309057453] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [-5 Amps]
[ign gazebo-1] [INFO] [1669844929.309392440] [power_controller]: Continue Override Winding Current (Torque) (8.126s)
[ign gazebo-1] [INFO] [1669844929.805343471] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [-5 Amps]
[ign gazebo-1] [INFO] [1669844929.805594567] [power_controller]: Continue Override Winding Current (Torque) (8.586s)
[ign gazebo-1] [INFO] [1669844930.308674380] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [-5 Amps]
[ign gazebo-1] [INFO] [1669844930.309228245] [power_controller]: Continue Override Winding Current (Torque) (9.057s)
[ign gazebo-1] [INFO] [1669844930.785959988] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [-5 Amps]
[ign gazebo-1] [INFO] [1669844930.786311505] [power_controller]: Continue Override Winding Current (Torque) (9.506s)
[ign gazebo-1] [INFO] [1669844931.241362445] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [-5 Amps]
[ign gazebo-1] [INFO] [1669844931.241601907] [power_controller]: Continue Override Winding Current (Torque) (9.927s)
[ign gazebo-1] [INFO] [1669844931.655020514] [power_controller]: [ROS 2 Power Control] PCWindCurrCommand Received [-5 Amps]
[ign gazebo-1] [INFO] [1669844931.655737093] [power_controller]: Continue Override Winding Current (Torque) (10.315s)
[ign gazebo-1] terminate called after throwing an instance of 'rclcpp::exceptions::RCLError'

andermi · 2022-11-30T22:34:12Z

[ign gazebo-1] terminate called after throwing an instance of 'rclcpp::exceptions::RCLError'
[ign gazebo-1] what(): failed to send response: cannot publish data, at /tmp/binarydeb/ros-galactic-rmw-cyclonedds-cpp-0.22.5/src/rmw_node.cpp:4041, at /tmp/binarydeb/ros-galactic-rcl-3.1.3/src/rcl/service.c:287
...
rclcpp::Service<buoy_interfaces::srv::PCWindCurrCommand>::send_response(rmw_request_id_t&, buoy_interfaces::srv::PCWindCurrCommand_Response<std::allocator >&)
[ign gazebo-1] #6 Object "/opt/ros/galactic/lib/librclcpp.so", at 0x7ff594312b5c, in rclcpp::exceptions::throw_from_rcl_error(int, std::__cxx11::basic_string<char, std::char_traits, std::allocator > const&, rcutils_error_state_t const*, void (*)())

@mjcarroll, anything that concerns you here at a glance? I'm guessing it's just something gone wrong in my callback lamda, though.

andermi · 2022-12-01T01:40:22Z

@hamilton8415, @mjcarroll , I can get the issue to happen by rapidly hitting up-arrow, enter. The error is inside rmw_node.cpp

[fixture_server-1] terminate called after throwing an instance of 'rclcpp::exceptions::RCLError'
[fixture_server-1]   what():  failed to send response: cannot publish data, at /tmp/binarydeb/ros-galactic-rmw-cyclonedds-cpp-0.22.5/src/rmw_node.cpp:4041, at /tmp/binarydeb/ros-galactic-rcl-3.1.3/src/rcl/service.c:287
[ERROR] [fixture_server-1]: process has died

hamilton8415 · 2022-12-01T04:39:31Z

Yep, up-arrow enter, centipede style. I certainly wasn't typing the command in 400ms, that'd be impressive I think.

mjcarroll · 2022-12-01T14:07:39Z

Is there something in the service response that is not re-entrant? My guess would be that we are using the multithreaded executor and a second (or third) service response is clobbering the first.

andermi · 2022-12-01T18:13:16Z

something in the service response that is not re-entrant?

@mjcarroll, I am using a multithreaded executor with a spin_once loop:

auto spin = [this]()
{
  while (rclcpp::ok() && !stop_) {
    ros_->executor_->spin_once();
  }
};
thread_executor_spin_ = std::thread(spin);

the class members in the service callback are all protected by mutexes (in a low/high priority lock pattern):

// high priority cmd access
std::unique_lock next_lock(services_->next_access_mutex_);
std::unique_lock cmd_lock(services_->command_mutex_);
next_lock.unlock();

if (valid_range.from_value > command_value ||
command_value > valid_range.to_value)
{
  command_value = std::min(
    std::max(
      command_value,
      valid_range.from_value),
    valid_range.to_value);

  result = buoy_interfaces::msg::PBCommandResponse::BAD_INPUT;
}

services_command_value = command_value;

services_command = true;
new_command = true;

cmd_lock.unlock();

andermi · 2022-12-01T18:19:30Z

I ran another test from within pbcmd when I run pc_WindCurr 10 where I have it send the command as fast as it can in a while loop. It doesn't crash in this mode. So, is it possible that pbcmd may sometimes quit and "hang up" on the service response before it gets sent?

in pbcmd I tell it to await self.pc_wind_curr_future_ so I figured that would keep it from exiting the program prematurely

andermi · 2022-12-01T18:28:39Z

@hamilton8415, since the crash issue doesn't happen programmatically and only when the user is "playing centipede" with pbcmd, I might just call it ok for now, thoughts?

hamilton8415 · 2022-12-01T18:49:30Z

Yeah, for now I can see that. But, I think this one will turn back up so will need to be addressed eventually is my guess. Tough to have it crash from monkeys poking at the keyboard...

andermi · 2022-12-01T19:14:06Z

FYI, to reproduce:
in buoy_sim, checkout andermi/fix_override_timeouts
in buoy_msgs, checkout andermi/tweak_pbcmd
and then, ros2 launch buoy_sim mbari_wec.launch.py
and finally, watch -n0 -- pc_WindCurr 10 (this will use a repeat of 0.1s)
it will eventually crash

it doesn't seem to crash if I use watch -n1

andermi · 2022-12-01T20:14:52Z

@hamilton8415, in attempting to solve the problem by making it go away... I wonder if we could just have the user provide an optional argument for rate or duration of the override if they want more than just one call? This would avoid the centipede typing and crash since it works fine sending fast programmatically.

andermi · 2022-12-05T21:39:12Z

@hamilton8415 @mjcarroll, was as simple as putting a rate limit on the executor spin_once loop in the controller plugin.

Signed-off-by: Michael Anderson <[email protected]>

…rf/buoy_sim into andermi/fix_override_timeouts

Signed-off-by: Michael Anderson <[email protected]>

andermi · 2022-12-05T21:47:38Z

@hamilton8415 I dare you to break it again!

hamilton8415 · 2022-12-05T22:58:49Z

Oh man, I am sure I can! I'm talented that way.. :).

hamilton8415 · 2022-12-09T05:04:46Z

I am back in California and back in the game. I was not however able to make this crash again as before, so that looks fixed. I did notice a surprising behavior in which the winding current timeout length seems to depend on the size of the winding current over-ride. A pc_WindCurr 10 (or 15) set's it at the value for the 2 second timeout. Larger settings (i.e. pc_WindCurr 20 (or 25) sets the value for a longer time, depending as I have seen it on the size of the setting. There's some interplay here so perhaps there's an explanation, but I can't think of it at the moment. See the plot...

andermi · 2022-12-09T21:28:02Z

surprising behavior in which the winding current timeout length seems to depend on the size of the winding current over-ride

I'm not able to reproduce that. What I am seeing (after printing times) is that 2 seconds always passes in sim time (both from the ros clock and from the gazebo clock) but real time (wall time) taken increases (more than 2 seconds) as the magnitude of winding current override increases. This means the real-time factor of the sim is bogging down during the override presumably because it takes the solver longer to converge?

What I am seeing is that the winding current is not remaining constant during the command. But maybe this is because the piston hasn't settled yet when I'm trying this...

hamilton8415 · 2022-12-09T21:34:30Z

OK, that's interesting. I think you're supposition that the electro-hydraulic solution is taking longer makes sense. Also, I can't quite imagine a bug that would cause the timeout to be specific to the size of the command. My bad for mis-interpeting the plot-juggler time axis. I say merge and move on with our weekends! :)

andermi · 2022-12-09T21:42:59Z

@hamilton8415 Putting my controls hat on and looking at my plot above, it looks like we've introduced an unstable zero somewhere in the winding current. Is that realistic? Or, do we need to get that out of the sim?

andermi · 2022-12-09T21:45:13Z

@hamilton8415 specifically here... I commanded -10

andermi · 2022-12-09T21:48:18Z

@hamilton8415 well... those spikes only seem to happen when the piston isn't quite settled yet at the beginning I suppose. So, maybe false alarm? Here it is after 600 seconds...

hamilton8415 · 2022-12-09T22:17:18Z

Yeah, I believe the oscillations are due to the simulated pressure relief valve and speed limiter. It's a bit hard to visualize, but remember that when the motor hits >5000RPM the commanded motor torque will be reduced to keep it from over-spinning. I think you'll see a correlation between those winding current reductions form the target and a large RPM value. It's not super physical though as we don't model the inertia of the motor rotor, so I don't have a great interpretation.

hamilton8415 · 2022-12-09T22:20:11Z

Another detail is that when the simulation currently starts the buoy is hovering above the water, this dumps a ton of power into the PTO and we see very large RPM's and powers for that first moment. I am not sure how faithful that representation is to reality, and so far have chosen to worry about that later, so I've been concentrating on examining the behaviors after those transients go away. For better or worse...

sending commands mid-override did not extend timeout

57595d7

Signed-off-by: Michael Anderson <[email protected]>

andermi requested a review from hamilton8415 November 30, 2022 21:26

andermi mentioned this pull request Nov 30, 2022

Tweak pbcmd osrf/mbari_wec_utils#37

Merged

Merge branch 'main' into andermi/fix_override_timeouts

ca76f7e

andermi added 3 commits December 5, 2022 13:45

rate limit on executor spin_once to stop pbcmd crashes

8d6b1d0

Signed-off-by: Michael Anderson <[email protected]>

Merge branch 'andermi/fix_override_timeouts' of https://github.com/os…

d345162

…rf/buoy_sim into andermi/fix_override_timeouts

linter

1c84486

Signed-off-by: Michael Anderson <[email protected]>

andermi merged commit a92b334 into main Dec 9, 2022

andermi deleted the andermi/fix_override_timeouts branch December 9, 2022 21:49

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix override command timeouts #110

Fix override command timeouts #110

andermi commented Nov 30, 2022

hamilton8415 commented Nov 30, 2022 •

edited by mjcarroll

Loading

hamilton8415 commented Nov 30, 2022

andermi commented Nov 30, 2022

andermi commented Nov 30, 2022

hamilton8415 commented Nov 30, 2022 •

edited by mjcarroll

Loading

hamilton8415 commented Nov 30, 2022 •

edited by mjcarroll

Loading

andermi commented Nov 30, 2022 •

edited

Loading

andermi commented Dec 1, 2022

hamilton8415 commented Dec 1, 2022

mjcarroll commented Dec 1, 2022

andermi commented Dec 1, 2022

andermi commented Dec 1, 2022 •

edited

Loading

andermi commented Dec 1, 2022

hamilton8415 commented Dec 1, 2022

andermi commented Dec 1, 2022 •

edited

Loading

andermi commented Dec 1, 2022

andermi commented Dec 5, 2022

andermi commented Dec 5, 2022

hamilton8415 commented Dec 5, 2022

hamilton8415 commented Dec 9, 2022

andermi commented Dec 9, 2022 •

edited

Loading

hamilton8415 commented Dec 9, 2022

andermi commented Dec 9, 2022

andermi commented Dec 9, 2022

andermi commented Dec 9, 2022

hamilton8415 commented Dec 9, 2022

hamilton8415 commented Dec 9, 2022

Fix override command timeouts #110

Fix override command timeouts #110

Conversation

andermi commented Nov 30, 2022

hamilton8415 commented Nov 30, 2022 • edited by mjcarroll Loading

hamilton8415 commented Nov 30, 2022

andermi commented Nov 30, 2022

andermi commented Nov 30, 2022

hamilton8415 commented Nov 30, 2022 • edited by mjcarroll Loading

hamilton8415 commented Nov 30, 2022 • edited by mjcarroll Loading

andermi commented Nov 30, 2022 • edited Loading

andermi commented Dec 1, 2022

hamilton8415 commented Dec 1, 2022

mjcarroll commented Dec 1, 2022

andermi commented Dec 1, 2022

andermi commented Dec 1, 2022 • edited Loading

andermi commented Dec 1, 2022

hamilton8415 commented Dec 1, 2022

andermi commented Dec 1, 2022 • edited Loading

andermi commented Dec 1, 2022

andermi commented Dec 5, 2022

andermi commented Dec 5, 2022

hamilton8415 commented Dec 5, 2022

hamilton8415 commented Dec 9, 2022

andermi commented Dec 9, 2022 • edited Loading

hamilton8415 commented Dec 9, 2022

andermi commented Dec 9, 2022

andermi commented Dec 9, 2022

andermi commented Dec 9, 2022

hamilton8415 commented Dec 9, 2022

hamilton8415 commented Dec 9, 2022

hamilton8415 commented Nov 30, 2022 •

edited by mjcarroll

Loading

hamilton8415 commented Nov 30, 2022 •

edited by mjcarroll

Loading

hamilton8415 commented Nov 30, 2022 •

edited by mjcarroll

Loading

andermi commented Nov 30, 2022 •

edited

Loading

andermi commented Dec 1, 2022 •

edited

Loading

andermi commented Dec 1, 2022 •

edited

Loading

andermi commented Dec 9, 2022 •

edited

Loading