Aarch64 reverse debugging test is unreliable
Host environment
- Operating system: Fedora 41
- Architecture: x86
- QEMU flavor: qemu-system-aarch64
- QEMU version: v10.0-rc3
- Command line:
QEMU_TEST_FLAKY_TESTS=1 pyvenv/bin/avocado run tests/avocado/reverse_debugging.py:ReverseDebugging_AArch64.test_aarch64_virt
Description of problem
The reverse-debugging test for the aarch64 target is not working reliably, especially if the host system is under load, approx. 1 or 2 out of 10 test runs fail. The log looks like this:
2025-04-14 10:24:35,042 test L0310 INFO | INIT 1-ReverseDebugging_AArch64.test_aarch64_virt
2025-04-14 10:24:35,043 parameters L0142 DEBUG| PARAMS (key=timeout, path=*, default=10) => 10
2025-04-14 10:24:35,043 test L0338 DEBUG| Test metadata:
2025-04-14 10:24:35,043 test L0340 DEBUG| filename: /.../tmp/qemu-build/tests/avocado/reverse_debugging.py
2025-04-14 10:24:35,044 test L0346 DEBUG| teststmpdir: /var/tmp/avocado_w5d2bkam
2025-04-14 10:24:35,044 test L0536 INFO | START 1-ReverseDebugging_AArch64.test_aarch64_virt
2025-04-14 10:24:35,044 test L0207 DEBUG| DATA (filename=output.expected) => NOT FOUND (data sources: variant, test, file)
2025-04-14 10:24:35,045 parameters L0142 DEBUG| PARAMS (key=arch, path=*, default=aarch64) => 'aarch64'
2025-04-14 10:24:35,045 parameters L0142 DEBUG| PARAMS (key=cpu, path=*, default=cortex-a53) => 'cortex-a53'
2025-04-14 10:24:35,046 parameters L0142 DEBUG| PARAMS (key=qemu_bin, path=*, default=./qemu-system-aarch64) => './qemu-system-aarch64'
2025-04-14 10:24:35,272 parameters L0142 DEBUG| PARAMS (key=machine, path=*, default=virt) => 'virt'
2025-04-14 10:24:35,290 test L0465 DEBUG| Test workdir initialized at: /var/tmp/.avocado-taskky_yb2qf/test-results/tmp_dir56wqq7g0/1-ReverseDebugging_AArch64.test_aarch64_virt
2025-04-14 10:24:35,290 process L0658 INFO | Running '/.../tmp/qemu-build/qemu-img create -f qcow2 /var/tmp/.avocado-taskky_yb2qf/test-results/tmp_dir56wqq7g0/1-ReverseDebugging_AArch64.test_aarch64_virt/disk.qcow2 128M'
2025-04-14 10:24:35,347 process L0470 DEBUG| [stdout] Formatting '/var/tmp/.avocado-taskky_yb2qf/test-results/tmp_dir56wqq7g0/1-ReverseDebugging_AArch64.test_aarch64_virt/disk.qcow2', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=134217728 lazy_refcounts=off refcount_bits=16
2025-04-14 10:24:35,393 process L0739 INFO | Command '/.../tmp/qemu-build/qemu-img create -f qcow2 /var/tmp/.avocado-taskky_yb2qf/test-results/tmp_dir56wqq7g0/1-ReverseDebugging_AArch64.test_aarch64_virt/disk.qcow2 128M' finished with 0 after 0.100170269s
2025-04-14 10:24:35,475 __init__ L0314 DEBUG| QEMUMachine "28fc0d7d-bd0a-44c0-afa8-f24a1800132f" created
2025-04-14 10:24:35,475 __init__ L0315 DEBUG| QEMUMachine "28fc0d7d-bd0a-44c0-afa8-f24a1800132f" temp_dir: /var/tmp/.avocado-taskky_yb2qf/test-results/tmp_dir56wqq7g0/1-ReverseDebugging_AArch64.test_aarch64_virt/qemu-machine-052_8e_k
2025-04-14 10:24:35,475 __init__ L0316 DEBUG| QEMUMachine "28fc0d7d-bd0a-44c0-afa8-f24a1800132f" log_dir: /var/tmp/.avocado-taskky_yb2qf/test-results/1-ReverseDebugging_AArch64.test_aarch64_virt
2025-04-14 10:24:36,195 __init__ L0314 DEBUG| QEMUMachine "3f348d83-7aa3-4381-9919-389bc85ed85b" created
2025-04-14 10:24:36,196 __init__ L0315 DEBUG| QEMUMachine "3f348d83-7aa3-4381-9919-389bc85ed85b" temp_dir: /var/tmp/.avocado-taskky_yb2qf/test-results/tmp_dir56wqq7g0/1-ReverseDebugging_AArch64.test_aarch64_virt/qemu-machine-vxlortdq
2025-04-14 10:24:36,196 __init__ L0316 DEBUG| QEMUMachine "3f348d83-7aa3-4381-9919-389bc85ed85b" log_dir: /var/tmp/.avocado-taskky_yb2qf/test-results/1-ReverseDebugging_AArch64.test_aarch64_virt
2025-04-14 10:24:37,623 stacktrace L0039 ERROR|
2025-04-14 10:24:37,628 stacktrace L0041 ERROR| Reproduced traceback from: /usr/lib/python3.13/site-packages/avocado/core/test.py:793
2025-04-14 10:24:37,643 stacktrace L0045 ERROR| Traceback (most recent call last):
2025-04-14 10:24:37,643 stacktrace L0045 ERROR| File "/usr/lib/python3.13/site-packages/avocado/core/decorators.py", line 90, in wrapper
2025-04-14 10:24:37,643 stacktrace L0045 ERROR| return function(obj, *args, **kwargs)
2025-04-14 10:24:37,643 stacktrace L0045 ERROR| File "/.../tmp/qemu-build/tests/avocado/reverse_debugging.py", line 239, in test_aarch64_virt
2025-04-14 10:24:37,644 stacktrace L0045 ERROR| self.reverse_debugging(
2025-04-14 10:24:37,644 stacktrace L0045 ERROR| ~~~~~~~~~~~~~~~~~~~~~~^
2025-04-14 10:24:37,644 stacktrace L0045 ERROR| args=('-kernel', kernel_path))
2025-04-14 10:24:37,644 stacktrace L0045 ERROR| ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2025-04-14 10:24:37,644 stacktrace L0045 ERROR| File "/.../tmp/qemu-build/tests/avocado/reverse_debugging.py", line 179, in reverse_debugging
2025-04-14 10:24:37,644 stacktrace L0045 ERROR| if self.vm_get_icount(vm) == last_icount - 1:
2025-04-14 10:24:37,644 stacktrace L0045 ERROR| ~~~~~~~~~~~~~~~~~~^^^^
2025-04-14 10:24:37,644 stacktrace L0045 ERROR| File "/.../tmp/qemu-build/tests/avocado/reverse_debugging.py", line 100, in vm_get_icount
2025-04-14 10:24:37,644 stacktrace L0045 ERROR| return vm.qmp('query-replay')['return']['icount']
2025-04-14 10:24:37,644 stacktrace L0045 ERROR| ~~~~~~^^^^^^^^^^^^^^^^
2025-04-14 10:24:37,645 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/machine/machine.py", line 711, in qmp
2025-04-14 10:24:37,645 stacktrace L0045 ERROR| ret = self._qmp.cmd_raw(cmd, args=qmp_args)
2025-04-14 10:24:37,645 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/legacy.py", line 208, in cmd_raw
2025-04-14 10:24:37,645 stacktrace L0045 ERROR| return self.cmd_obj(qmp_cmd)
2025-04-14 10:24:37,645 stacktrace L0045 ERROR| ~~~~~~~~~~~~^^^^^^^^^
2025-04-14 10:24:37,645 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/legacy.py", line 186, in cmd_obj
2025-04-14 10:24:37,645 stacktrace L0045 ERROR| self._sync(
2025-04-14 10:24:37,645 stacktrace L0045 ERROR| ~~~~~~~~~~^
2025-04-14 10:24:37,645 stacktrace L0045 ERROR| # pylint: disable=protected-access
2025-04-14 10:24:37,645 stacktrace L0045 ERROR| ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2025-04-14 10:24:37,646 stacktrace L0045 ERROR| ...<5 lines>...
2025-04-14 10:24:37,646 stacktrace L0045 ERROR| self._timeout
2025-04-14 10:24:37,646 stacktrace L0045 ERROR| ^^^^^^^^^^^^^
2025-04-14 10:24:37,646 stacktrace L0045 ERROR| )
2025-04-14 10:24:37,646 stacktrace L0045 ERROR| ^
2025-04-14 10:24:37,646 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/legacy.py", line 102, in _sync
2025-04-14 10:24:37,646 stacktrace L0045 ERROR| return self._aloop.run_until_complete(
2025-04-14 10:24:37,647 stacktrace L0045 ERROR| ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^
2025-04-14 10:24:37,647 stacktrace L0045 ERROR| asyncio.wait_for(future, timeout=timeout)
2025-04-14 10:24:37,647 stacktrace L0045 ERROR| ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2025-04-14 10:24:37,647 stacktrace L0045 ERROR| )
2025-04-14 10:24:37,647 stacktrace L0045 ERROR| ^
2025-04-14 10:24:37,647 stacktrace L0045 ERROR| File "/usr/lib64/python3.13/asyncio/base_events.py", line 725, in run_until_complete
2025-04-14 10:24:37,647 stacktrace L0045 ERROR| return future.result()
2025-04-14 10:24:37,647 stacktrace L0045 ERROR| ~~~~~~~~~~~~~^^
2025-04-14 10:24:37,647 stacktrace L0045 ERROR| File "/usr/lib64/python3.13/asyncio/tasks.py", line 507, in wait_for
2025-04-14 10:24:37,648 stacktrace L0045 ERROR| return await fut
2025-04-14 10:24:37,648 stacktrace L0045 ERROR| ^^^^^^^^^
2025-04-14 10:24:37,648 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/qmp_client.py", line 547, in _raw
2025-04-14 10:24:37,648 stacktrace L0045 ERROR| return await self._execute(msg, assign_id=assign_id)
2025-04-14 10:24:37,648 stacktrace L0045 ERROR| ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2025-04-14 10:24:37,648 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/qmp_client.py", line 496, in _execute
2025-04-14 10:24:37,648 stacktrace L0045 ERROR| return await self._reply(exec_id)
2025-04-14 10:24:37,648 stacktrace L0045 ERROR| ^^^^^^^^^^^^^^^^^^^^^^^^^^
2025-04-14 10:24:37,648 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/qmp_client.py", line 463, in _reply
2025-04-14 10:24:37,648 stacktrace L0045 ERROR| raise result
2025-04-14 10:24:37,648 stacktrace L0045 ERROR| qemu.qmp.qmp_client.ExecInterruptedError: Disconnected
2025-04-14 10:24:37,649 stacktrace L0046 ERROR|
2025-04-14 10:24:37,649 test L0798 DEBUG| Local variables:
2025-04-14 10:24:37,671 test L0801 DEBUG| -> obj <class 'reverse_debugging.ReverseDebugging_AArch64'>: 1-ReverseDebugging_AArch64.test_aarch64_virt
2025-04-14 10:24:37,671 test L0801 DEBUG| -> args <class 'tuple'>: ()
2025-04-14 10:24:37,671 test L0801 DEBUG| -> kwargs <class 'dict'>: {}
2025-04-14 10:24:37,671 test L0801 DEBUG| -> condition <class 'str'>: 1
2025-04-14 10:24:37,671 test L0801 DEBUG| -> function <class 'function'>: <function ReverseDebugging_AArch64.test_aarch64_virt at 0x7fc6d4cc87c0>
2025-04-14 10:24:37,672 test L0801 DEBUG| -> message <class 'str'>: Test is unstable on GitLab
2025-04-14 10:24:37,672 test L0801 DEBUG| -> negate <class 'bool'>: True
2025-04-14 10:24:37,673 stacktrace L0039 ERROR|
2025-04-14 10:24:37,673 stacktrace L0041 ERROR| Reproduced traceback from: /usr/lib/python3.13/site-packages/avocado/core/test.py:819
2025-04-14 10:24:37,678 stacktrace L0045 ERROR| Traceback (most recent call last):
2025-04-14 10:24:37,679 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/machine/machine.py", line 580, in _soft_shutdown
2025-04-14 10:24:37,679 stacktrace L0045 ERROR| self.qmp('quit')
2025-04-14 10:24:37,679 stacktrace L0045 ERROR| ~~~~~~~~^^^^^^^^
2025-04-14 10:24:37,679 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/machine/machine.py", line 711, in qmp
2025-04-14 10:24:37,679 stacktrace L0045 ERROR| ret = self._qmp.cmd_raw(cmd, args=qmp_args)
2025-04-14 10:24:37,679 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/legacy.py", line 208, in cmd_raw
2025-04-14 10:24:37,679 stacktrace L0045 ERROR| return self.cmd_obj(qmp_cmd)
2025-04-14 10:24:37,679 stacktrace L0045 ERROR| ~~~~~~~~~~~~^^^^^^^^^
2025-04-14 10:24:37,679 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/legacy.py", line 192, in cmd_obj
2025-04-14 10:24:37,680 stacktrace L0045 ERROR| self._qmp._raw(qmp_cmd, assign_id=False),
2025-04-14 10:24:37,680 stacktrace L0045 ERROR| ~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^
2025-04-14 10:24:37,680 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/protocol.py", line 155, in _wrapper
2025-04-14 10:24:37,680 stacktrace L0045 ERROR| raise StateError(emsg, proto.runstate, required_state)
2025-04-14 10:24:37,680 stacktrace L0045 ERROR| qemu.qmp.protocol.StateError: QMPClient is disconnecting. Call disconnect() to return to IDLE state.
2025-04-14 10:24:37,680 stacktrace L0045 ERROR|
2025-04-14 10:24:37,680 stacktrace L0045 ERROR| During handling of the above exception, another exception occurred:
2025-04-14 10:24:37,680 stacktrace L0045 ERROR|
2025-04-14 10:24:37,680 stacktrace L0045 ERROR| Traceback (most recent call last):
2025-04-14 10:24:37,680 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/machine/machine.py", line 611, in _do_shutdown
2025-04-14 10:24:37,681 stacktrace L0045 ERROR| self._soft_shutdown(timeout)
2025-04-14 10:24:37,681 stacktrace L0045 ERROR| ~~~~~~~~~~~~~~~~~~~^^^^^^^^^
2025-04-14 10:24:37,681 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/machine/machine.py", line 583, in _soft_shutdown
2025-04-14 10:24:37,681 stacktrace L0045 ERROR| self._close_qmp_connection()
2025-04-14 10:24:37,681 stacktrace L0045 ERROR| ~~~~~~~~~~~~~~~~~~~~~~~~~~^^
2025-04-14 10:24:37,681 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/machine/machine.py", line 501, in _close_qmp_connection
2025-04-14 10:24:37,681 stacktrace L0045 ERROR| self._qmp.close()
2025-04-14 10:24:37,681 stacktrace L0045 ERROR| ~~~~~~~~~~~~~~~^^
2025-04-14 10:24:37,681 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/legacy.py", line 281, in close
2025-04-14 10:24:37,681 stacktrace L0045 ERROR| self._sync(
2025-04-14 10:24:37,681 stacktrace L0045 ERROR| ~~~~~~~~~~^
2025-04-14 10:24:37,682 stacktrace L0045 ERROR| self._qmp.disconnect()
2025-04-14 10:24:37,682 stacktrace L0045 ERROR| ^^^^^^^^^^^^^^^^^^^^^^
2025-04-14 10:24:37,682 stacktrace L0045 ERROR| )
2025-04-14 10:24:37,682 stacktrace L0045 ERROR| ^
2025-04-14 10:24:37,682 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/legacy.py", line 102, in _sync
2025-04-14 10:24:37,682 stacktrace L0045 ERROR| return self._aloop.run_until_complete(
2025-04-14 10:24:37,682 stacktrace L0045 ERROR| ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^
2025-04-14 10:24:37,682 stacktrace L0045 ERROR| asyncio.wait_for(future, timeout=timeout)
2025-04-14 10:24:37,682 stacktrace L0045 ERROR| ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2025-04-14 10:24:37,682 stacktrace L0045 ERROR| )
2025-04-14 10:24:37,682 stacktrace L0045 ERROR| ^
2025-04-14 10:24:37,683 stacktrace L0045 ERROR| File "/usr/lib64/python3.13/asyncio/base_events.py", line 725, in run_until_complete
2025-04-14 10:24:37,683 stacktrace L0045 ERROR| return future.result()
2025-04-14 10:24:37,683 stacktrace L0045 ERROR| ~~~~~~~~~~~~~^^
2025-04-14 10:24:37,683 stacktrace L0045 ERROR| File "/usr/lib64/python3.13/asyncio/tasks.py", line 507, in wait_for
2025-04-14 10:24:37,683 stacktrace L0045 ERROR| return await fut
2025-04-14 10:24:37,683 stacktrace L0045 ERROR| ^^^^^^^^^
2025-04-14 10:24:37,683 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/protocol.py", line 399, in disconnect
2025-04-14 10:24:37,683 stacktrace L0045 ERROR| await self._wait_disconnect()
2025-04-14 10:24:37,683 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/protocol.py", line 719, in _wait_disconnect
2025-04-14 10:24:37,683 stacktrace L0045 ERROR| await all_defined_tasks # Raise Exceptions from the bottom half.
2025-04-14 10:24:37,684 stacktrace L0045 ERROR| ^^^^^^^^^^^^^^^^^^^^^^^
2025-04-14 10:24:37,684 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/protocol.py", line 870, in _bh_loop_forever
2025-04-14 10:24:37,684 stacktrace L0045 ERROR| await async_fn()
2025-04-14 10:24:37,684 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/protocol.py", line 908, in _bh_recv_message
2025-04-14 10:24:37,684 stacktrace L0045 ERROR| msg = await self._recv()
2025-04-14 10:24:37,684 stacktrace L0045 ERROR| ^^^^^^^^^^^^^^^^^^
2025-04-14 10:24:37,684 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/protocol.py", line 1009, in _recv
2025-04-14 10:24:37,684 stacktrace L0045 ERROR| message = await self._do_recv()
2025-04-14 10:24:37,684 stacktrace L0045 ERROR| ^^^^^^^^^^^^^^^^^^^^^
2025-04-14 10:24:37,684 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/qmp_client.py", line 402, in _do_recv
2025-04-14 10:24:37,684 stacktrace L0045 ERROR| msg_bytes = await self._readline()
2025-04-14 10:24:37,685 stacktrace L0045 ERROR| ^^^^^^^^^^^^^^^^^^^^^^
2025-04-14 10:24:37,685 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/qmp/protocol.py", line 977, in _readline
2025-04-14 10:24:37,685 stacktrace L0045 ERROR| raise EOFError
2025-04-14 10:24:37,685 stacktrace L0045 ERROR| EOFError
2025-04-14 10:24:37,685 stacktrace L0045 ERROR|
2025-04-14 10:24:37,685 stacktrace L0045 ERROR| The above exception was the direct cause of the following exception:
2025-04-14 10:24:37,685 stacktrace L0045 ERROR|
2025-04-14 10:24:37,685 stacktrace L0045 ERROR| Traceback (most recent call last):
2025-04-14 10:24:37,685 stacktrace L0045 ERROR| File "/.../tmp/qemu-build/tests/avocado/avocado_qemu/__init__.py", line 372, in tearDown
2025-04-14 10:24:37,685 stacktrace L0045 ERROR| vm.shutdown()
2025-04-14 10:24:37,685 stacktrace L0045 ERROR| ~~~~~~~~~~~^^
2025-04-14 10:24:37,686 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/machine/machine.py", line 648, in shutdown
2025-04-14 10:24:37,686 stacktrace L0045 ERROR| self._do_shutdown(timeout)
2025-04-14 10:24:37,686 stacktrace L0045 ERROR| ~~~~~~~~~~~~~~~~~^^^^^^^^^
2025-04-14 10:24:37,686 stacktrace L0045 ERROR| File "/.../devel/qemu/python/qemu/machine/machine.py", line 618, in _do_shutdown
2025-04-14 10:24:37,686 stacktrace L0045 ERROR| raise AbnormalShutdown("Could not perform graceful shutdown") \
2025-04-14 10:24:37,686 stacktrace L0045 ERROR| from exc
2025-04-14 10:24:37,686 stacktrace L0045 ERROR| qemu.machine.machine.AbnormalShutdown: Could not perform graceful shutdown
2025-04-14 10:24:37,686 stacktrace L0046 ERROR|
2025-04-14 10:24:37,694 test L0941 ERROR| Traceback (most recent call last):
2025-04-14 10:24:37,694 test L0941 ERROR| File "/usr/lib/python3.13/site-packages/avocado/core/test.py", line 881, in _run_avocado
raise test_exception
2025-04-14 10:24:37,694 test L0941 ERROR| File "/usr/lib/python3.13/site-packages/avocado/core/test.py", line 788, in _run_avocado
testMethod()
~~~~~~~~~~^^
2025-04-14 10:24:37,695 test L0941 ERROR| File "/usr/lib/python3.13/site-packages/avocado/core/decorators.py", line 90, in wrapper
return function(obj, *args, **kwargs)
2025-04-14 10:24:37,695 test L0941 ERROR| File "/.../tmp/qemu-build/tests/avocado/reverse_debugging.py", line 239, in test_aarch64_virt
self.reverse_debugging(
~~~~~~~~~~~~~~~~~~~~~~^
args=('-kernel', kernel_path))
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2025-04-14 10:24:37,695 test L0941 ERROR| File "/.../tmp/qemu-build/tests/avocado/reverse_debugging.py", line 179, in reverse_debugging
if self.vm_get_icount(vm) == last_icount - 1:
~~~~~~~~~~~~~~~~~~^^^^
2025-04-14 10:24:37,695 test L0941 ERROR| File "/.../tmp/qemu-build/tests/avocado/reverse_debugging.py", line 100, in vm_get_icount
return vm.qmp('query-replay')['return']['icount']
~~~~~~^^^^^^^^^^^^^^^^
2025-04-14 10:24:37,695 test L0941 ERROR| File "/.../devel/qemu/python/qemu/machine/machine.py", line 711, in qmp
ret = self._qmp.cmd_raw(cmd, args=qmp_args)
2025-04-14 10:24:37,695 test L0941 ERROR| File "/.../devel/qemu/python/qemu/qmp/legacy.py", line 208, in cmd_raw
return self.cmd_obj(qmp_cmd)
~~~~~~~~~~~~^^^^^^^^^
2025-04-14 10:24:37,695 test L0941 ERROR| File "/.../devel/qemu/python/qemu/qmp/legacy.py", line 186, in cmd_obj
self._sync(
~~~~~~~~~~^
# pylint: disable=protected-access
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
...<5 lines>...
self._timeout
^^^^^^^^^^^^^
)
^
2025-04-14 10:24:37,695 test L0941 ERROR| File "/.../devel/qemu/python/qemu/qmp/legacy.py", line 102, in _sync
return self._aloop.run_until_complete(
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^
asyncio.wait_for(future, timeout=timeout)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
)
^
2025-04-14 10:24:37,695 test L0941 ERROR| File "/usr/lib64/python3.13/asyncio/base_events.py", line 725, in run_until_complete
return future.result()
~~~~~~~~~~~~~^^
2025-04-14 10:24:37,695 test L0941 ERROR| File "/usr/lib64/python3.13/asyncio/tasks.py", line 507, in wait_for
return await fut
^^^^^^^^^
2025-04-14 10:24:37,696 test L0941 ERROR| File "/.../devel/qemu/python/qemu/qmp/qmp_client.py", line 547, in _raw
return await self._execute(msg, assign_id=assign_id)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2025-04-14 10:24:37,696 test L0941 ERROR| File "/.../devel/qemu/python/qemu/qmp/qmp_client.py", line 496, in _execute
return await self._reply(exec_id)
^^^^^^^^^^^^^^^^^^^^^^^^^^
2025-04-14 10:24:37,696 test L0941 ERROR| File "/.../devel/qemu/python/qemu/qmp/qmp_client.py", line 463, in _reply
raise result
2025-04-14 10:24:37,696 test L0941 ERROR| qemu.qmp.qmp_client.ExecInterruptedError: Disconnected
2025-04-14 10:24:37,696 test L0956 ERROR| ERROR 1-ReverseDebugging_AArch64.test_aarch64_virt -> ExecInterruptedError: Disconnected
2025-04-14 10:24:37,696 test L0948 INFO | Steps to reproduce
make check-venv- Run something in the background that keeps all CPUs busy
for ((x=0;x<20;x++)); do QEMU_TEST_FLAKY_TESTS=1 pyvenv/bin/avocado run tests/avocado/reverse_debugging.py:ReverseDebugging_AArch64.test_aarch64_virt ; done
Additional information
The problem can be reproduced with the test converted to the functional framework, too (that's where I noticed it first). In that case the stack trace looked like this:
$ QEMU_TEST_ALLOW_SLOW=1 QEMU_TEST_ALLOW_UNTRUSTED_CODE=1 QEMU_TEST_FLAKY_TESTS=1 QEMU_TEST_ALLOW_LARGE_STORAGE=1 ~/devel/qemu/tests/functional/test_aarch64_reverse_debug.py
TAP version 13
Traceback (most recent call last):
File "/.../devel/qemu/tests/functional/test_aarch64_reverse_debug.py", line 33, in test_aarch64_virt
self.reverse_debugging(args=('-kernel', kernel_path))
~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/.../devel/qemu/tests/functional/reverse_debugging.py", line 147, in reverse_debugging
pc = self.get_pc(g)
File "/.../devel/qemu/tests/functional/reverse_debugging.py", line 82, in get_pc
return self.get_reg(g, self.REG_PC)
~~~~~~~~~~~~^^^^^^^^^^^^^^^^
File "/.../devel/qemu/tests/functional/reverse_debugging.py", line 77, in get_reg
return self.get_reg_le(g, reg)
~~~~~~~~~~~~~~~^^^^^^^^
File "/.../devel/qemu/tests/functional/reverse_debugging.py", line 63, in get_reg_le
res = g.cmd(b'p%x' % reg)
File "/usr/lib/python3.13/site-packages/avocado/utils/gdb.py", line 783, in cmd
response_payload = self.decode(result)
File "/usr/lib/python3.13/site-packages/avocado/utils/gdb.py", line 738, in decode
raise InvalidPacketError
avocado.utils.gdb.InvalidPacketError
not ok 1 test_aarch64_reverse_debug.ReverseDebugging_AArch64.test_aarch64_virt
Traceback (most recent call last):
File "/.../devel/qemu/python/qemu/machine/machine.py", line 580, in _soft_shutdown
self.qmp('quit')
~~~~~~~~^^^^^^^^
File "/.../devel/qemu/python/qemu/machine/machine.py", line 711, in qmp
ret = self._qmp.cmd_raw(cmd, args=qmp_args)
File "/.../devel/qemu/python/qemu/qmp/legacy.py", line 208, in cmd_raw
return self.cmd_obj(qmp_cmd)
~~~~~~~~~~~~^^^^^^^^^
File "/.../devel/qemu/python/qemu/qmp/legacy.py", line 186, in cmd_obj
self._sync(
~~~~~~~~~~^
# pylint: disable=protected-access
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
...<5 lines>...
self._timeout
^^^^^^^^^^^^^
)
^
File "/.../devel/qemu/python/qemu/qmp/legacy.py", line 102, in _sync
return self._aloop.run_until_complete(
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^
asyncio.wait_for(future, timeout=timeout)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
)
^
File "/usr/lib64/python3.13/asyncio/base_events.py", line 725, in run_until_complete
return future.result()
~~~~~~~~~~~~~^^
File "/usr/lib64/python3.13/asyncio/tasks.py", line 507, in wait_for
return await fut
^^^^^^^^^
File "/.../devel/qemu/python/qemu/qmp/qmp_client.py", line 547, in _raw
return await self._execute(msg, assign_id=assign_id)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/.../devel/qemu/python/qemu/qmp/qmp_client.py", line 496, in _execute
return await self._reply(exec_id)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/.../devel/qemu/python/qemu/qmp/qmp_client.py", line 463, in _reply
raise result
qemu.qmp.qmp_client.ExecInterruptedError: Disconnected
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/.../devel/qemu/python/qemu/machine/machine.py", line 611, in _do_shutdown
self._soft_shutdown(timeout)
~~~~~~~~~~~~~~~~~~~^^^^^^^^^
File "/.../devel/qemu/python/qemu/machine/machine.py", line 583, in _soft_shutdown
self._close_qmp_connection()
~~~~~~~~~~~~~~~~~~~~~~~~~~^^
File "/.../devel/qemu/python/qemu/machine/machine.py", line 501, in _close_qmp_connection
self._qmp.close()
~~~~~~~~~~~~~~~^^
File "/.../devel/qemu/python/qemu/qmp/legacy.py", line 281, in close
self._sync(
~~~~~~~~~~^
self._qmp.disconnect()
^^^^^^^^^^^^^^^^^^^^^^
)
^
File "/.../devel/qemu/python/qemu/qmp/legacy.py", line 102, in _sync
return self._aloop.run_until_complete(
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^
asyncio.wait_for(future, timeout=timeout)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
)
^
File "/usr/lib64/python3.13/asyncio/base_events.py", line 725, in run_until_complete
return future.result()
~~~~~~~~~~~~~^^
File "/usr/lib64/python3.13/asyncio/tasks.py", line 507, in wait_for
return await fut
^^^^^^^^^
File "/.../devel/qemu/python/qemu/qmp/protocol.py", line 399, in disconnect
await self._wait_disconnect()
File "/.../devel/qemu/python/qemu/qmp/protocol.py", line 719, in _wait_disconnect
await all_defined_tasks # Raise Exceptions from the bottom half.
^^^^^^^^^^^^^^^^^^^^^^^
File "/.../devel/qemu/python/qemu/qmp/protocol.py", line 834, in _bh_close_stream
await wait_closed(self._writer)
File "/.../devel/qemu/python/qemu/qmp/util.py", line 130, in wait_closed
await writer.wait_closed()
File "/usr/lib64/python3.13/asyncio/streams.py", line 358, in wait_closed
await self._protocol._get_close_waiter(self)
File "/usr/lib64/python3.13/asyncio/selector_events.py", line 1067, in write
n = self._sock.send(data)
BrokenPipeError: [Errno 32] Broken pipe
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/.../devel/qemu/tests/functional/qemu_test/testcase.py", line 398, in tearDown
vm.shutdown()
~~~~~~~~~~~^^
File "/.../devel/qemu/python/qemu/machine/machine.py", line 648, in shutdown
self._do_shutdown(timeout)
~~~~~~~~~~~~~~~~~^^^^^^^^^
File "/.../devel/qemu/python/qemu/machine/machine.py", line 618, in _do_shutdown
raise AbnormalShutdown("Could not perform graceful shutdown") \
from exc
qemu.machine.machine.AbnormalShutdown: Could not perform graceful shutdown
not ok 1 test_aarch64_reverse_debug.ReverseDebugging_AArch64.test_aarch64_virt
1..1