Task statistics collection is racy
Michael Tokarev reported that debusine's CI is repeatedly failing on s390x in https://tracker.debian.org/pkg/qemu. I looked into the test artifacts and found that a piuparts task is failing like this: ``` Apr 29 08:55:11 ci-119-8f3f099c debusine-worker[11188]: Work request 13: Cleaning up Apr 29 08:55:11 ci-119-8f3f099c debusine-worker[11188]: Uploading /var/lib/debusine/worker/workdir/WR-13-1amm65qn/logs/cmd-output.log to https://ci-119-8f3f099c.localdomain/api/1.0/artifact/19/files/cmd-output.log/ Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: Uploading /var/lib/debusine/worker/workdir/WR-13-1amm65qn/logs/install.log to https://ci-119-8f3f099c.localdomain/api/1.0/artifact/19/files/install.log/ Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: Server notification channel closed Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: + Exception Group Traceback (most recent call last): Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | File "/usr/bin/debusine-worker", line 8, in <module> Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | sys.exit(entry_point()) Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | ~~~~~~~~~~~^^ Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | File "/usr/lib/python3/dist-packages/debusine/worker/__main__.py", line 67, in entry_point Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | main(sys.argv[1:]) Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | ~~~~^^^^^^^^^^^^^^ Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | File "/usr/lib/python3/dist-packages/debusine/worker/__main__.py", line 62, in main Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | asyncio.run(async_main()) Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | ~~~~~~~~~~~^^^^^^^^^^^^^^ Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | File "/usr/lib/python3.13/asyncio/runners.py", line 195, in run Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | return runner.run(main) Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | ~~~~~~~~~~^^^^^^ Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | File "/usr/lib/python3.13/asyncio/runners.py", line 118, in run Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | return self._loop.run_until_complete(task) Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^ Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | File "/usr/lib/python3.13/asyncio/base_events.py", line 725, in run_until_complete Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | return future.result() Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | ~~~~~~~~~~~~~^^ Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | File "/usr/lib/python3/dist-packages/debusine/worker/__main__.py", line 60, in async_main Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | await worker.main() Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | File "/usr/lib/python3/dist-packages/debusine/worker/_worker.py", line 340, in main Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | if event := await self.process_notifications(): Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | File "/usr/lib/python3/dist-packages/debusine/worker/_worker.py", line 355, in process_notifications Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | async with asyncio.TaskGroup() as tg: Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | ~~~~~~~~~~~~~~~~~^^ Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | File "/usr/lib/python3.13/asyncio/taskgroups.py", line 71, in __aexit__ Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | return await self._aexit(et, exc) Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | ^^^^^^^^^^^^^^^^^^^^^^^^^^ Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | File "/usr/lib/python3.13/asyncio/taskgroups.py", line 173, in _aexit Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | raise BaseExceptionGroup( Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | ...<2 lines>... Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | ) from None Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | ExceptionGroup: unhandled errors in a TaskGroup (1 sub-exception) Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: +-+---------------- 1 ---------------- Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | Traceback (most recent call last): Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | File "/usr/lib/python3/dist-packages/debusine/worker/_worker.py", line 511, in _request_and_execute_work_request Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | result = await runner.execute() Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | ^^^^^^^^^^^^^^^^^^^^^^ Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | File "/usr/lib/python3/dist-packages/debusine/worker/task_runner.py", line 265, in execute Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | async with CollectStatistics(self.task, self.statistics): Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | ~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | File "/usr/lib/python3/dist-packages/debusine/worker/task_runner.py", line 110, in __aexit__ Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | await self.collect_task Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | File "/usr/lib/python3/dist-packages/debusine/worker/task_runner.py", line 118, in collect Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | self.gather() Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | ~~~~~~~~~~~^^ Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | File "/usr/lib/python3/dist-packages/debusine/worker/task_runner.py", line 89, in gather Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | statistics = self.task.executor.get_statistics( Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | self.task.executor_instance Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | ) Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | File "/usr/lib/python3/dist-packages/debusine/tasks/executors/unshare.py", line 134, in get_statistics Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | statvfs = os.statvfs(instance._root) Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: | FileNotFoundError: [Errno 2] No such file or directory: '/var/lib/debusine/worker/workdir/WR-13-1amm65qn/unshare-5d9jdja1/root' Apr 29 08:55:12 ci-119-8f3f099c debusine-worker[11188]: +------------------------------------ Apr 29 08:55:14 ci-119-8f3f099c systemd[1]: debusine-worker.service: Main process exited, code=exited, status=1/FAILURE ``` The code here looks racy to me. `CollectStatistics.collect` calls `CollectStatistics.gather` in a loop while the task is running, which calls the `get_statistics` method on the executor. But both the unshare and Incus implementations of `get_statistics` have a similar bug: they check `instance.is_started` and then look up various properties of the instance, but because this is running in parallel with the task it's possible that the task will be cleaned up between the `is_started` check and the statistics queries themselves. All `get_statistics` implementations need to guard against this. It's probably simplest for them to just try the actual statistics queries and catch exceptions, rather than their current look-before-you-leap approach.
issue