python/Ice/asyncio failure (Windows)

[bernardnormier]

From https://github.com/zeroc-ice/ice/actions/runs/12351181365/job/34465600576?pr=3270:

*** [244/271] Running python/Ice/asyncio tests ***
[ running client/server test - 12/16/24 12:03:11 ]
- Config: ssl,x64
("C:\hostedtoolcache\windows\Python\3.13.1\x64\python.exe"  D:\a\ice\ice\python\test\TestHelper.py Server --Ice.Default.Host=127.0.0.1 --Test.BasePort=14000 --Ice.Warn.Connections=1 --Ice.Default.Protocol=ssl --Ice.IPv6=0 --IceSSL.*** --IceSSL.DefaultDir=D:\a\ice\ice\certs --IceSSL.CAs=cacert.pem --IceSSL.CertFile=server.p12 --Ice.ThreadPool.Server.Size=1 --Ice.ThreadPool.Server.SizeMax=3 --Ice.ThreadPool.Server.SizeWarn=0 --Ice.PrintAdapterReady=1 env={'PATH': 'D:\\a\\ice\\ice\\cpp\\bin\\x64\\Release', 'PYTHONPATH': 'D:\\a\\ice\\ice\\python\\python\\x64\\Release;D:\\a\\ice\\ice\\python\\python;D:\\a\\ice\\ice\\python\\test\\Ice\\asyncio'})
("C:\hostedtoolcache\windows\Python\3.13.1\x64\python.exe"  D:\a\ice\ice\python\test\TestHelper.py Client --Ice.Default.Host=127.0.0.1 --Test.BasePort=14000 --Ice.Warn.Connections=1 --Ice.Default.Protocol=ssl --Ice.IPv6=0 --IceSSL.*** --IceSSL.DefaultDir=D:\a\ice\ice\certs --IceSSL.CAs=cacert.pem --IceSSL.CertFile=client.p12 env={'PATH': 'D:\\a\\ice\\ice\\cpp\\bin\\x64\\Release', 'PYTHONPATH': 'D:\\a\\ice\\ice\\python\\python\\x64\\Release;D:\\a\\ice\\ice\\python\\python;D:\\a\\ice\\ice\\python\\test\\Ice\\asyncio'})
testing invocation... Executing <Task pending name='Task-1' coro=<Client.run.<locals>.runAsync() running at D:\a\ice\ice\python\test\Ice\asyncio\Client.py:18> wait_for=<Future pending cb=[wrap_future.<locals>.<lambda>() at D:\a\ice\ice\python\python\Ice\Future.py:48, Task.task_wakeup()] created at C:\hostedtoolcache\windows\Python\3.13.1\x64\Lib\asyncio\base_events.py:459> cb=[_run_until_complete_cb() at C:\hostedtoolcache\windows\Python\3.13.1\x64\Lib\asyncio\base_events.py:181] created at C:\hostedtoolcache\windows\Python\3.13.1\x64\Lib\asyncio\runners.py:100> took 0.132 seconds
ok
testing exceptions... ok
testing cancellation... ok
Executing <Task pending name='Task-1' coro=<Server.run.<locals>.runAsync() running at D:\a\ice\ice\python\test\Ice\asyncio\Server.py:28> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at C:\hostedtoolcache\windows\Python\3.13.1\x64\Lib\asyncio\futures.py:384, Task.task_wakeup()] created at C:\hostedtoolcache\windows\Python\3.13.1\x64\Lib\asyncio\base_events.py:459> cb=[_run_until_complete_cb() at C:\hostedtoolcache\windows\Python\3.13.1\x64\Lib\asyncio\base_events.py:181] created at C:\hostedtoolcache\windows\Python\3.13.1\x64\Lib\asyncio\runners.py:100> took 0.142 seconds
[ running client/server test - 12/16/24 12:03:13 ]
- Config: ws,compress,ipv6,serialize,mx,x64
("C:\hostedtoolcache\windows\Python\3.13.1\x64\python.exe"  D:\a\ice\ice\python\test\TestHelper.py Server --Ice.Default.Host=::1 --Test.BasePort=14000 --Ice.Warn.Connections=1 --Ice.Default.Protocol=ws --Ice.Override.Compress=1 --Ice.ThreadPool.Server.Serialize=1 --Ice.IPv6=1 --Ice.PreferIPv6Address=1 --Ice.Admin.Endpoints="tcp -h \"::1\"" --Ice.Admin.InstanceName=Server --IceMX.Metrics.Debug.GroupBy=id --IceMX.Metrics.Parent.GroupBy=parent --IceMX.Metrics.All.GroupBy=none --Ice.ThreadPool.Server.Size=1 --Ice.ThreadPool.Server.SizeMax=3 --Ice.ThreadPool.Server.SizeWarn=0 --Ice.PrintAdapterReady=1 env={'PATH': 'D:\\a\\ice\\ice\\cpp\\bin\\x64\\Release', 'PYTHONPATH': 'D:\\a\\ice\\ice\\python\\python\\x64\\Release;D:\\a\\ice\\ice\\python\\python;D:\\a\\ice\\ice\\python\\test\\Ice\\asyncio'})
("C:\hostedtoolcache\windows\Python\3.13.1\x64\python.exe"  D:\a\ice\ice\python\test\TestHelper.py Client --Ice.Default.Host=::1 --Test.BasePort=14000 --Ice.Warn.Connections=1 --Ice.Default.Protocol=ws --Ice.Override.Compress=1 --Ice.ThreadPool.Server.Serialize=1 --Ice.IPv6=1 --Ice.PreferIPv6Address=1 --Ice.Admin.Endpoints="tcp -h \"::1\"" --Ice.Admin.InstanceName=Client --IceMX.Metrics.Debug.GroupBy=id --IceMX.Metrics.Parent.GroupBy=parent --IceMX.Metrics.All.GroupBy=none env={'PATH': 'D:\\a\\ice\\ice\\cpp\\bin\\x64\\Release', 'PYTHONPATH': 'D:\\a\\ice\\ice\\python\\python\\x64\\Release;D:\\a\\ice\\ice\\python\\python;D:\\a\\ice\\ice\\python\\test\\Ice\\asyncio'})
testing invocation... ok
testing exceptions... ok
testing cancellation... Traceback (most recent call last):
  File "D:\a\ice\ice\python\test\TestHelper.py", line 89, in run
    helper.run(sys.argv[2:])
    ~~~~~~~~~~^^^^^^^^^^^^^^
  File "D:\a\ice\ice\python\test\Ice\asyncio\Client.py", line 20, in run
    asyncio.run(runAsync(), debug=True)
    ~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\hostedtoolcache\windows\Python\3.13.1\x64\Lib\asyncio\runners.py", line 194, in run
    return runner.run(main)
           ~~~~~~~~~~^^^^^^
  File "C:\hostedtoolcache\windows\Python\3.13.1\x64\Lib\asyncio\runners.py", line 118, in run
    return self._loop.run_until_complete(task)
           ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^
  File "C:\hostedtoolcache\windows\Python\3.13.1\x64\Lib\asyncio\base_events.py", line 720, in run_until_complete
    return future.result()
           ~~~~~~~~~~~~~^^
  File "D:\a\ice\ice\python\test\Ice\asyncio\Client.py", line 18, in runAsync
    await AllTests.allTestsAsync(self, communicator)
  File "D:\a\ice\ice\python\test\Ice\asyncio\AllTests.py", line 58, in allTestsAsync
    await asyncioFuture
Ice.InvocationCanceledException: invocation canceled
!! 12/16/24 12:03:14809 error: communicator not destroyed during global destruction.

[pepone]

I have been running this for a while on Windows with Python 3.13.1 but cannot reproduce.

Looking at the code we have

ice/python/python/Ice/Future.py

Lines 20 to 56 in 075234d

	def wrap_future(future, *, loop=None):
	"""Wrap Ice.Future object into an asyncio.Future."""
	if isinstance(future, asyncio.Future):
	return future
	assert isinstance(future, FutureBase), "Ice.Future is expected, got {!r}".format(
	future
	)
	def forwardCompletion(sourceFuture, targetFuture):
	if not targetFuture.done():
	if sourceFuture.cancelled():
	targetFuture.cancel()
	elif sourceFuture.exception():
	targetFuture.set_exception(sourceFuture.exception())
	else:
	targetFuture.set_result(sourceFuture.result())
	if loop is None:
	loop = asyncio.get_event_loop()
	asyncioFuture = loop.create_future()
	if future.done():
	# As long as no done callbacks are registered, completing the asyncio future should be thread safe
	# even if the future is constructed with a loop which isn't the current thread's loop.
	forwardCompletion(future, asyncioFuture)
	else:
	asyncioFuture.add_done_callback(
	lambda f: forwardCompletion(asyncioFuture, future)
	)
	future.add_done_callback(
	lambda f: loop.call_soon_threadsafe(
	forwardCompletion, future, asyncioFuture
	)
	)
	return asyncioFuture

Here the wrap future takes care of forwarding state changes between Ice.Future and asyncio.future.

In the failing test the cancel call correspond to InvocationFuture.cancel

ice/python/python/Ice/InvocationFuture.py

Lines 20 to 22 in 075234d

	def cancel(self):
	self._asyncInvocationContext.cancel()
	return Future.cancel(self)

Which first cancels the C++ requests through the AsyncInvocationContext, and then cancels the Ice.Future.

My understanding here is that the cancelation of the C++ asynchronous request always set the exception asynchronously.

ice/cpp/src/Ice/OutgoingAsync.cpp

Line 293 in 075234d

handler->asyncRequestCanceled(shared_from_this(), ex);

ice/cpp/src/Ice/ConnectionI.cpp

Lines 874 to 877 in 075234d

	if (outAsync->exception(ex))
	{
	outAsync->invokeExceptionAsync();
	}

ice/cpp/src/Ice/OutgoingAsync.cpp

Lines 74 to 82 in 075234d

	OutgoingAsyncBase::invokeExceptionAsync()
	{
	//
	// CommunicatorDestroyedException is the only exception that can propagate directly from this method.
	//
	_instance->clientThreadPool()->execute(
	[self = shared_from_this()]() { self->invokeException(); },
	_cachedConnection);
	}

So here I would expect that Future.cancel() always runs before than the exception handler, because this code is run with the GIL locked, and the C++ exception is set asynchronously, when the IcePy code exception handler runs it have to wait to acquire the GIL.

But the error seems to indicate otherwise, for example it seems like the set_exception callback was run before that Future.cancel was called. This will explain why asyncio future was completed with an exception instead of being canceled.