Any help regarding how to debug this would be greatly appreciated as I am not sure it is something worth reporting as a bug yet and it seems to be some race condition with the co-routines.
Python 3.12.9 (main, Mar 31 2025, 00:00:00) [GCC 14.2.1 20240912 (Red Hat 14.2.1-3)] on linux
I hope I understand this right but in my case no cancellations take place, the code that waits for the threads looks like this:
slot_workers = sorted([*graph.workers.values()], key=lambda x: x.params["name"])
to_traverse = [graph.traverse_object_trees(s, params) for s in slot_workers]
asyncio.get_event_loop().run_until_complete(
asyncio.wait_for(asyncio.gather(*to_traverse), self.job.timeout or None)
)
and the hang happens at the very end where all these workers are done with the subprocesses they have spawned (from what I can see in the related logs).
I could try to get a smaller reproducer but this will likely take time. Note that I didn’t have such troubles for 1-2 years with the same code and what I am reporting above is recent.
Indeed, I am aware but could not migrate yet. I still don’t expect this to make up for the difference for the time being though but thanks for mentioning this.
Ok, I could finally reproduce this again with the necessary added prints like
@@ -335,23 +335,43 @@ class TestRunner(RunnerInterface):
for worker in graph.workers.values():
if not worker.spawner:
worker.spawner = SpawnerDispatcher(self.job.config, self.job)[
worker.params["nets_spawner"]
].obj
if not worker.start():
raise RuntimeError(f"Failed to start environment {worker.id}")
slot_workers = sorted([*graph.workers.values()], key=lambda x: x.params["name"])
to_traverse = [graph.traverse_object_trees(s, params) for s in slot_workers]
- asyncio.get_event_loop().run_until_complete(
- asyncio.wait_for(asyncio.gather(*to_traverse), self.job.timeout or None)
- )
+ try:
+ asyncio.get_event_loop().run_until_complete(
+ asyncio.wait_for(
+ asyncio.shield(asyncio.gather(*to_traverse)),
+ 86400 or self.job.timeout or None,
+ )
+ )
+ except asyncio.TimeoutError as error:
+ logging.error(error)
+ import stackscope
+
+ logging.critical(
+ "Timeout exceeded. Printing stacks of all running coroutines:"
+ )
+ all_coros = [
+ t.get_coro() for t in asyncio.all_tasks(asyncio.get_event_loop())
+ ]
+ for coro in all_coros:
+ logging.critical(stackscope.extract(coro))
+ except KeyboardInterrupt as error:
+ logging.info(str(error))
+ self.job.interrupted_reason = str(error)
+ # summary.add("INTERRUPTED")
def run_suite(self, job: Job, test_suite: TestSuite) -> set[str]:
"""
Run one or more tests and report with test result.
:param job: job that includes the test suite
:param test_suite: test suite with some tests to run
:returns: a set with types of test failures
"""
summary = set()
and what I get out of this is
│2025-09-13 01:31:07,729 avocado.job.avocado_i2n.plugins.runner runner L0353 ERROR|
│2025-09-13 01:31:07,797 avocado.job.avocado_i2n.plugins.runner runner L0356 CRITI| Timeout exceeded. Printing stacks of all running coroutines:
│2025-09-13 01:31:07,823 avocado.job.avocado_i2n.plugins.runner runner L0363 CRITI| stackscope.Stack of <coroutine object TestRunner._update_status at 0x7fc239b85240> (most recent call last):
│╠ TestRunner._update_status in avocado_i2n.plugins.runner at /usr/lib/python3.13/site-packages/avocado_i2n/plugins/runner.py:83
│║ └ await asyncio.sleep(0.05)
│╠ sleep in asyncio.tasks at /usr/lib64/python3.13/asyncio/tasks.py:718
│║ └ return await future
│╚ <_asyncio.FutureIter object at 0x7fc2396e7d30> │
│2025-09-13 01:31:07,827 avocado.job.avocado_i2n.plugins.runner runner L0363 CRITI| stackscope.Stack of <coroutine object StatusServer.serve_forever at 0x7fc23a39cdc0> (most recent call last):
│╠ StatusServer.serve_forever in avocado.core.status.server at /usr/lib/python3.13/site-packages/avocado/core/status/server.py:44
│║ └ await self._server_task.serve_forever()
│╠ Server.serve_forever in asyncio.base_events at /usr/lib64/python3.13/asyncio/base_events.py:379
│║ └ await self._serving_forever_fut
│╚ <_asyncio.FutureIter object at 0x7fc239a06890> │
│2025-09-13 01:31:07,856 avocado.job.avocado_i2n.plugins.runner runner L0363 CRITI| stackscope.Stack of <coroutine object TestGraph.traverse_object_trees at 0x7fc240cc92d0> (most recent call last):
│╠ TestGraph.traverse_object_trees in avocado_i2n.cartgraph.graph at /usr/lib/python3.13/site-packages/avocado_i2n/cartgraph/graph.py:2187
│║ └ await self.traverse_node(next, worker, params)
│╠ TestGraph.traverse_node in avocado_i2n.cartgraph.graph at /usr/lib/python3.13/site-packages/avocado_i2n/cartgraph/graph.py:2005
│║ └ status = await self.runner.run_test_node(test_node)
│╠ TestRunner.run_test_node in avocado_i2n.plugins.runner at /usr/lib/python3.13/site-packages/avocado_i2n/plugins/runner.py:241
│║ └ await self.run_test_task(node)
│╠ TestRunner.run_test_task in avocado_i2n.plugins.runner at /usr/lib/python3.13/site-packages/avocado_i2n/plugins/runner.py:211
│║ └ await Worker(
│╠ Worker.run in avocado.core.task.statemachine at /usr/lib/python3.13/site-packages/avocado/core/task/statemachine.py:505
│║ └ await self.monitor()
│╠ Worker.monitor in avocado.core.task.statemachine at /usr/lib/python3.13/site-packages/avocado/core/task/statemachine.py:439
│║ └ await asyncio.sleep(0.1)
│╠ sleep in asyncio.tasks at /usr/lib64/python3.13/asyncio/tasks.py:718
│║ └ return await future
│╚ <_asyncio.FutureIter object at 0x7fc23833b250>