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

Race condition in cetautomatix causing global robots failure #47

Open
3wnbr1 opened this issue Sep 4, 2021 · 1 comment
Open

Race condition in cetautomatix causing global robots failure #47

3wnbr1 opened this issue Sep 4, 2021 · 1 comment
Assignees
Labels
bug Something isn't working enhancement New feature or request unsatisfying This will not be used

Comments

@3wnbr1
Copy link
Member

3wnbr1 commented Sep 4, 2021

#39 reverted a mitigation against this race condition

The ideal design would be prevent cetautomatix initialization completion as long as an odom message hasn't been received. We can't block the constructor's completion as this would result onto the odom callback handler not being called. We could instead use a boolean semaphore within the node to let know each subroutine if the node is ready and early return if it is not / report as not not ready yet.

Short term mitigation was to position with dummy values but this is impractical and can cause side effects.

@3wnbr1 3wnbr1 added bug Something isn't working enhancement New feature or request unsatisfying This will not be used labels Sep 4, 2021
@3wnbr1
Copy link
Member Author

3wnbr1 commented Sep 4, 2021

2021-09-03T09:47:55.5984865Z [cetautomatix-4] [INFO] [1630662475.597532453] [asterix.cetautomatix]: Cetautomatix ROS node has been started
2021-09-03T09:47:55.6103044Z INFO: Starting extern controller for robot "asterix".
2021-09-03T09:47:55.6839627Z [drive-1] [INFO] [1630662475.680287837] [asterix.drive_node]: Drive node initialised
2021-09-03T09:47:55.7288031Z [localisation-3] [INFO] [1630662475.727966062] [asterix.localisation_node]: Default side is blue
2021-09-03T09:47:55.7683600Z [cetautomatix-4] [INFO] [1630662475.767489380] [asterix.tree]: ... connected to action server [navigate_to_pose][FromBlackboard/NavigateToPose]
2021-09-03T09:47:55.7780850Z [INFO] [1630662475.777957917] [game_manager]: Starting match
2021-09-03T09:47:55.7866582Z INFO: Starting extern controller for robot "asterix_vlx_manager".
2021-09-03T09:47:55.7972162Z [controller_server-6] [INFO] [1630662475.796343258] [asterix.local_costmap.local_costmap]: Timed out waiting for transform from base_link to map to become available, tf error: Could not find a connection between 'map' and 'base_link' because they are not part of the same tree.Tf has two or more unconnected trees.
2021-09-03T09:47:56.2973049Z [controller_server-6] [INFO] [1630662476.296330907] [asterix.local_costmap.local_costmap]: Timed out waiting for transform from base_link to map to become available, tf error: Could not find a connection between 'map' and 'base_link' because they are not part of the same tree.Tf has two or more unconnected trees.
2021-09-03T09:47:56.5264016Z INFO: Start HTML5 animation export
2021-09-03T09:47:56.5264946Z 
2021-09-03T09:47:56.5290522Z [cetautomatix-4] [INFO] [1630662476.528254045] [asterix.cetautomatix]: Triggered robot starter
2021-09-03T09:47:56.6746149Z [strategix-3] [INFO] [1630662476.673307145] [strategix_action_server]: GET asterix
2021-09-03T09:47:56.6767863Z [strategix-3] [INFO] [1630662476.673916053] [strategix_action_server]: AVAILABLE: ['PHARE_BLEU', 'MANCHE1', 'MANCHE2', 'GOB1', 'GOB2', 'GOB3', 'GOB4', 'GOB5', 'GOB6', 'GOB7', 'GOB8', 'GOB9', 'GOB10', 'GOB11', 'GOB12', 'GOB13', 'GOB14', 'GOB15', 'GOB16', 'GOB17', 'GOB18', 'GOB19', 'GOB20', 'GOB21', 'GOB22', 'GOB23', 'GOB24']
2021-09-03T09:47:56.6770158Z [cetautomatix-4] [!] Actuators are in simulation mode. No python3-smbus was found !
2021-09-03T09:47:56.6772220Z [cetautomatix-4] [!] RPI Servos are in simulation mode. python3-gpiozero was found !
2021-09-03T09:47:56.7970896Z [controller_server-6] [INFO] [1630662476.796318756] [asterix.local_costmap.local_costmap]: Timed out waiting for transform from base_link to map to become available, tf error: Could not find a connection between 'map' and 'base_link' because they are not part of the same tree.Tf has two or more unconnected trees.
2021-09-03T09:47:57.0969747Z [cetautomatix-4] Traceback (most recent call last):
2021-09-03T09:47:57.0971334Z [cetautomatix-4]   File "/home/runner/work/cdfr/cdfr/install/cetautomatix/lib/cetautomatix/cetautomatix", line 11, in <module>
2021-09-03T09:47:57.0972943Z [cetautomatix-4]     load_entry_point('cetautomatix', 'console_scripts', 'cetautomatix')()
2021-09-03T09:47:57.0974734Z [cetautomatix-4]   File "/home/runner/work/cdfr/cdfr/build/cetautomatix/cetautomatix/main.py", line 44, in main
2021-09-03T09:47:57.0975792Z [cetautomatix-4]     executor.spin()
2021-09-03T09:47:57.0976904Z [cetautomatix-4]   File "/opt/ros/foxy/lib/python3.8/site-packages/rclpy/executors.py", line 290, in spin
2021-09-03T09:47:57.0977921Z [cetautomatix-4]     self.spin_once()
2021-09-03T09:47:57.0979007Z [cetautomatix-4]   File "/opt/ros/foxy/lib/python3.8/site-packages/rclpy/executors.py", line 711, in spin_once
2021-09-03T09:47:57.0980124Z [cetautomatix-4]     raise handler.exception()
2021-09-03T09:47:57.0981242Z [cetautomatix-4]   File "/opt/ros/foxy/lib/python3.8/site-packages/rclpy/task.py", line 239, in __call__
2021-09-03T09:47:57.0982259Z [cetautomatix-4]     self._handler.send(None)
2021-09-03T09:47:57.0983402Z [cetautomatix-4]   File "/opt/ros/foxy/lib/python3.8/site-packages/rclpy/executors.py", line 426, in handler
2021-09-03T09:47:57.0984506Z [cetautomatix-4]     await call_coroutine(entity, arg)
2021-09-03T09:47:57.0985827Z [cetautomatix-4]   File "/opt/ros/foxy/lib/python3.8/site-packages/rclpy/executors.py", line 340, in _execute_timer
2021-09-03T09:47:57.0987108Z [cetautomatix-4]     await await_or_execute(tmr.callback)
2021-09-03T09:47:57.0988729Z [cetautomatix-4]   File "/opt/ros/foxy/lib/python3.8/site-packages/rclpy/executors.py", line 118, in await_or_execute
2021-09-03T09:47:57.0989933Z [cetautomatix-4]     return callback(*args)
2021-09-03T09:47:57.0991335Z [cetautomatix-4]   File "/opt/ros/foxy/lib/python3.8/site-packages/py_trees_ros/trees.py", line 561, in _tick_tock_timer_callback
2021-09-03T09:47:57.0992654Z [cetautomatix-4]     self.tick(pre_tick_handler, post_tick_handler)
2021-09-03T09:47:57.0993819Z [cetautomatix-4]   File "/opt/ros/foxy/lib/python3.8/site-packages/py_trees/trees.py", line 353, in tick
2021-09-03T09:47:57.0995440Z [cetautomatix-4]     for node in self.root.tick():
2021-09-03T09:47:57.0996762Z [cetautomatix-4]   File "/opt/ros/foxy/lib/python3.8/site-packages/py_trees/composites.py", line 458, in tick
2021-09-03T09:47:57.0998106Z [cetautomatix-4]     for node in child.tick():
2021-09-03T09:47:57.0999234Z [cetautomatix-4]   File "/opt/ros/foxy/lib/python3.8/site-packages/py_trees/composites.py", line 346, in tick
2021-09-03T09:47:57.1000411Z [cetautomatix-4]     for node in child.tick():
2021-09-03T09:47:57.1001577Z [cetautomatix-4]   File "/opt/ros/foxy/lib/python3.8/site-packages/py_trees/composites.py", line 581, in tick
2021-09-03T09:47:57.1002841Z [cetautomatix-4]     for node in child.tick():
2021-09-03T09:47:57.1003955Z [cetautomatix-4]   File "/opt/ros/foxy/lib/python3.8/site-packages/py_trees/decorators.py", line 136, in tick
2021-09-03T09:47:57.1005085Z [cetautomatix-4]     for node in self.decorated.tick():
2021-09-03T09:47:57.1006490Z [cetautomatix-4]   File "/opt/ros/foxy/lib/python3.8/site-packages/py_trees/composites.py", line 458, in tick
2021-09-03T09:47:57.1007470Z [cetautomatix-4]     for node in child.tick():
2021-09-03T09:47:57.1008760Z [cetautomatix-4]   File "/opt/ros/foxy/lib/python3.8/site-packages/py_trees/behaviour.py", line 274, in tick
2021-09-03T09:47:57.1010007Z [cetautomatix-4]     new_status = self.update()
2021-09-03T09:47:57.1011231Z [cetautomatix-4]   File "/home/runner/work/cdfr/cdfr/build/cetautomatix/cetautomatix/custom_behaviours.py", line 20, in update
2021-09-03T09:47:57.1012749Z [cetautomatix-4]     best_action = self.robot.compute_best_action(available_actions)
2021-09-03T09:47:57.1015496Z [cetautomatix-4]   File "/home/runner/work/cdfr/cdfr/build/cetautomatix/cetautomatix/robot.py", line 308, in compute_best_action
2021-09-03T09:47:57.1016764Z [cetautomatix-4]     (action.position[0] - self.position[0]) ** 2
2021-09-03T09:47:57.1018020Z [cetautomatix-4] AttributeError: 'Robot' object has no attribute 'position'
2021-09-03T09:47:57.2645128Z [localisation-3] [INFO] [1630662477.259656726] [asterix.localisation_node]: Localisation node is ready
2021-09-03T09:47:57.2974114Z [controller_server-6] [INFO] [1630662477.296493308] [asterix.local_costmap.local_costmap]: start
2021-09-03T09:47:57.3488834Z [lifecycle_manager-12] [INFO] [1630662477.347560477] [asterix.lifecycle_manager_navigation]: �[34m�[1mActivating planner_server�[0m�[0m
2021-09-03T09:47:57.3497148Z [planner_server-7] [INFO] [1630662477.348497589] [asterix.planner_server]: Activating
2021-09-03T09:47:57.3499252Z [planner_server-7] [INFO] [1630662477.348534790] [asterix.global_costmap.global_costmap]: Activating
2021-09-03T09:47:57.3501056Z [planner_server-7] [INFO] [1630662477.348550090] [asterix.global_costmap.global_costmap]: Checking transform
2021-09-03T09:47:57.3502599Z [planner_server-7] [INFO] [1630662477.348654191] [asterix.global_costmap.global_costmap]: start
2021-09-03T09:47:57.4004229Z [planner_server-7] [INFO] [1630662477.398878849] [asterix.planner_server]: Activating plugin GridBased of type NavfnPlanner
2021-09-03T09:47:57.4041503Z [lifecycle_manager-12] [INFO] [1630662477.402899702] [asterix.lifecycle_manager_navigation]: �[34m�[1mActivating recoveries_server�[0m�[0m
2021-09-03T09:47:57.4044756Z [recoveries_server-8] [INFO] [1630662477.403164006] [asterix.recoveries_server]: Activating
2021-09-03T09:47:57.4048054Z [recoveries_server-8] [INFO] [1630662477.403197106] [asterix.recoveries_server]: Activating spin
2021-09-03T09:47:57.4050195Z [recoveries_server-8] [INFO] [1630662477.403209706] [asterix.recoveries_server]: Activating backup
2021-09-03T09:47:57.4053092Z [recoveries_server-8] [INFO] [1630662477.403218706] [asterix.recoveries_server]: Activating wait
2021-09-03T09:47:57.4067922Z [lifecycle_manager-12] [INFO] [1630662477.404594424] [asterix.lifecycle_manager_navigation]: �[34m�[1mActivating bt_navigator�[0m�[0m
2021-09-03T09:47:57.4071844Z [lifecycle_manager-12] [INFO] [1630662477.405434035] [asterix.lifecycle_manager_navigation]: �[34m�[1mActivating waypoint_follower�[0m�[0m
2021-09-03T09:47:57.4073736Z [bt_navigator-9] [INFO] [1630662477.404793027] [asterix.bt_navigator]: Activating
2021-09-03T09:47:57.4075661Z [waypoint_follower-10] [INFO] [1630662477.405628338] [asterix.waypoint_follower]: Activating
2021-09-03T09:47:57.4097741Z [lifecycle_manager-12] [INFO] [1630662477.406930355] [asterix.lifecycle_manager_navigation]: �[34m�[1mActivating map_server�[0m�[0m
2021-09-03T09:47:57.4123814Z [map_server-11] [INFO] [1630662477.407151458] [asterix.map_server]: Activating
2021-09-03T09:47:57.4140347Z [planner_server-7] [INFO] [1630662477.407825867] [asterix.global_costmap.global_costmap]: StaticLayer: Resizing costmap to 352 X 302 at 0.020000 m/pix
2021-09-03T09:47:57.4147590Z [controller_server-6] [INFO] [1630662477.407877367] [asterix.local_costmap.local_costmap]: StaticLayer: Resizing costmap to 352 X 302 at 0.020000 m/pix
2021-09-03T09:47:57.4153488Z [lifecycle_manager-12] [INFO] [1630662477.410217598] [asterix.lifecycle_manager_navigation]: �[34m�[1mManaged nodes are active�[0m�[0m
2021-09-03T09:47:57.4856610Z [ERROR] [cetautomatix-4]: process has died [pid 23380, exit code 1, cmd '/home/runner/work/cdfr/cdfr/install/cetautomatix/lib/cetautomatix/cetautomatix --ros-args -r __ns:=/asterix --params-file /tmp/tmp8e0rs9_o -r /tf:=tf -r /tf_static:=tf_static'].

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working enhancement New feature or request unsatisfying This will not be used
Projects
None yet
Development

No branches or pull requests

3 participants