check for shutdown while waiting for a service response to avoid hang during shutdown

[wjwwood]

Should fix #102

[wjwwood]

CI up to lifecycle which is where the problem occurred. I'll run broader CI afterwards if it passes:

• Linux
• Linux-aarch64
• macOS
• Windows

[pbaughman]

@wjwwood I'm away from the office right now, but I'll test this in the setup that hangs as soon as I'm in tomorrow morning

[wjwwood]

Full CI:

• Linux
• Linux-aarch64
• macOS
• Windows

[pbaughman]

@wjwwood A few new stack-traces:

[INFO] [lifecycle_talker-1]: process has finished cleanly [pid 9573]
Future exception was never retrieved
future: <Future finished exception=AttributeError("'LifecycleNode' object has no attribute '_LifecycleNode___logger'",)>
Traceback (most recent call last):
  File "/usr/lib/python3.6/concurrent/futures/thread.py", line 56, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/home/pete.baughman/gc/apex_ws/build/launch_ros/launch_ros/actions/lifecycle_node.py", line 99, in _call_change_state
    self.___logger.warning(
AttributeError: 'LifecycleNode' object has no attribute '_LifecycleNode___logger'

Followed-by (and possibly the cause of):

Exception ignored in: <coroutine object LaunchService._process_one_event at 0x7f286fff4308>
Traceback (most recent call last):
  File "/home/pete.baughman/gc/apex_ws/build/launch/launch/launch_service.py", line 286, in _process_one_event
    next_event = await self.__context._event_queue.get()
  File "/usr/lib/python3.6/asyncio/queues.py", line 169, in get
    getter.cancel()  # Just in case getter is not done yet.
  File "/usr/lib/python3.6/asyncio/base_events.py", line 591, in call_soon
    self._check_closed()
  File "/usr/lib/python3.6/asyncio/base_events.py", line 377, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed

Looks like a simple typo. Too many underbars

Edit Weirdly, the same issue is on line 81 but nobody ever noticed?

[pbaughman]

@wjwwood Even after fixing the triple-underbar calls to logger, I still see:

[INFO] [lifecycle_talker-1]: process has finished cleanly [pid 11072]
Future exception was never retrieved
future: <Future finished exception=InvalidHandle('Tried to use a handle that has been destroyed.',)>
Traceback (most recent call last):
  File "/usr/lib/python3.6/concurrent/futures/thread.py", line 56, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/home/pete.baughman/gc/apex_ws/build/launch_ros/launch_ros/actions/lifecycle_node.py", line 79, in _call_change_state
    while not self.__rclpy_change_state_client.wait_for_service(timeout_sec=1.0):
  File "/home/pete.baughman/gc/apex_ws/install/rclpy/lib/python3.6/site-packages/rclpy/client.py", line 160, in wait_for_service
    while self.context.ok() and not self.service_is_ready() and timeout_sec > 0.0:
  File "/home/pete.baughman/gc/apex_ws/install/rclpy/lib/python3.6/site-packages/rclpy/client.py", line 143, in service_is_ready
    with self.handle as capsule:
  File "/home/pete.baughman/gc/apex_ws/install/rclpy/lib/python3.6/site-packages/rclpy/handle.py", line 146, in __enter__
    return self._get_capsule()
  File "/home/pete.baughman/gc/apex_ws/install/rclpy/lib/python3.6/site-packages/rclpy/handle.py", line 128, in _get_capsule
    raise InvalidHandle('Tried to use a handle that has been destroyed.')
rclpy.handle.InvalidHandle: Tried to use a handle that has been destroyed.

And then a little later:

Exception ignored in: <coroutine object LaunchService._process_one_event at 0x7f29034d7c50>
Traceback (most recent call last):
  File "/home/pete.baughman/gc/apex_ws/build/launch/launch/launch_service.py", line 286, in _process_one_event
    next_event = await self.__context._event_queue.get()
  File "/usr/lib/python3.6/asyncio/queues.py", line 169, in get
    getter.cancel()  # Just in case getter is not done yet.
  File "/usr/lib/python3.6/asyncio/base_events.py", line 591, in call_soon
    self._check_closed()
  File "/usr/lib/python3.6/asyncio/base_events.py", line 377, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed
Task was destroyed but it is pending!

Note that this is a 'sometimes' stack trace, not an all-the-time stack trace

[wjwwood]

Edit Weirdly, the same issue is on line 81 but nobody ever noticed?

It was just never executed since it's a rare race condition.

---

For the latest traceback (the first of the two in the latest comment), that's not even part of the modified code... It happens before it on line 79:

File "/home/pete.baughman/gc/apex_ws/build/launch_ros/launch_ros/actions/lifecycle_node.py", line 79, in _call_change_state
while not self.__rclpy_change_state_client.wait_for_service(timeout_sec=1.0):

I think that's likely the other issue where (rclcpp_/rclpy_)shutdown causes functions to fail afterwards.

For that one, I think we should just catch rclpy.handle.InvalidHandle and pass on it.

[wjwwood]

I fixed the typos in 398cf8c

[pbaughman]

@wjwwood Do you propose we deal with the invalid handle in another PR or this one? or third option not worry about it

[wjwwood]

If it's causing a problem we can go ahead and fix it I guess, but it would be good to know if the original problem is fixed (it was a hang not a crash) and that this fix doesn't cause the crashes you see.

[pbaughman]

I'm pretty confident that the original issue (hang) is resolved. I could make it happen in 10 minutes before your change, and I let your change run for about 90 minutes without hanging.

[hidmic]

I wonder if ROSSpecificLaunchStartup should somehow provide this feature, any future ROS service calls done from within launch will run into the same problem, no?

[wjwwood]

I wonder if ROSSpecificLaunchStartup should somehow provide this feature, any future ROS service calls done from within launch will run into the same problem, no?

Maybe so, but I think this is the only case so far. In general you need to think about these issues, as who ever wrote this (probably me) was thinking with the wait_for_service() call that's already checking for shutdown. It might help to refactor it later to avoid code duplication though.

[wjwwood]

New CI:

• Linux
• Linux-aarch64
• macOS (I canceled this because we're backed up on the farm and it was ok before)
• Windows

[pbaughman]

@wjwwood Any update on this?

[wjwwood]

Running CI again:

• Linux
• Linux-aarch64
• macOS
• Windows

[wjwwood]

Comparing the CI results to nightly, e.g. https://ci.ros2.org/view/nightly/job/nightly_linux_release/1389/testReport/, I've manually verified that all the failures were preexisting.

macOS is hung in the ros2cli tests (known issue), so I'm going to ignore that one.

Despite these issues, I'm going to merge this if I can find a review, so that some downstream users can bring the patch in.

[jacobperron]

LGTM