ReverseDebugging_ppc64 avocado test is not working reliably Description of problem: The tests/avocado/reverse_debugging.py:ReverseDebugging_ppc64.test_ppc64_powernv test is sometimes failing in the gitlab-CI. Looking at the logs, it seems like QEMU is dying early here, so this might be a real bug and not only an issue with the test. Full debug.log from the failing job: ``` 08:28:31 DEBUG| PARAMS (key=arch, path=*, default=ppc64) => 'ppc64' 08:28:31 DEBUG| PARAMS (key=cpu, path=*, default=None) => None 08:28:31 DEBUG| PARAMS (key=qemu_bin, path=*, default=./qemu-system-ppc64) => './qemu-system-ppc64' 08:28:31 DEBUG| PARAMS (key=machine, path=*, default=powernv) => 'powernv' 08:28:31 INFO | creating qcow2 image for VM snapshots 08:28:31 INFO | Running '/builds/thuth/qemu/build/qemu-img create -f qcow2 /builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/disk.qcow2 128M' 08:28:31 DEBUG| [stdout] Formatting '/builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/disk.qcow2', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=134217728 lazy_refcounts=off refcount_bits=16 08:28:31 INFO | Command '/builds/thuth/qemu/build/qemu-img create -f qcow2 /builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/disk.qcow2 128M' finished with 0 after 0.024550681999926383s 08:28:31 DEBUG| QEMUMachine "1646a50b-5d2a-405b-8636-45a38b5fde30" created 08:28:31 DEBUG| QEMUMachine "1646a50b-5d2a-405b-8636-45a38b5fde30" temp_dir: /builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/qemu-machine-uq5k4nlc 08:28:31 DEBUG| QEMUMachine "1646a50b-5d2a-405b-8636-45a38b5fde30" log_dir: /builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv 08:28:31 INFO | recording the execution... 08:28:31 DEBUG| Using selector: EpollSelector 08:28:31 DEBUG| Registering . 08:28:31 DEBUG| VM launch command: './qemu-system-ppc64 -display none -vga none -chardev socket,id=mon,fd=5 -mon chardev=mon,mode=control -machine powernv -chardev socket,id=console,fd=19 -serial chardev:console -icount shift=7,rr=record,rrfile=/builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/replay.bin,rrsnapshot=init -net none -drive file=/builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/disk.qcow2,if=none' 08:28:31 DEBUG| Transitioning from 'Runstate.IDLE' to 'Runstate.CONNECTING'. 08:28:31 DEBUG| Connecting with existing socket: fd=12, family=, type= 08:28:31 DEBUG| Connected. 08:28:31 DEBUG| Awaiting greeting ... 08:28:31 DEBUG| <-- { "QMP": { "version": { "qemu": { "micro": 90, "minor": 1, "major": 8 }, "package": "v5.2.0-26508-gaf9264da80" }, "capabilities": [ "oob" ] } } 08:28:31 DEBUG| Negotiating capabilities ... 08:28:31 DEBUG| --> { "execute": "qmp_capabilities", "arguments": { "enable": [ "oob" ] } } 08:28:31 DEBUG| <-- { "return": {} } 08:28:31 DEBUG| Transitioning from 'Runstate.CONNECTING' to 'Runstate.RUNNING'. 08:28:31 DEBUG| Opening console socket 08:28:31 DEBUG| --> { "execute": "query-replay" } 08:28:31 DEBUG| <-- { "return": { "icount": 5521801, "mode": "record", "filename": "/builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/replay.bin" } } 08:28:31 DEBUG| --> { "execute": "query-replay" } 08:28:31 DEBUG| [ 0.230392217,5] OPAL v7.0 starting... 08:28:31 DEBUG| [ 0.230674939,7] initial console log level: memory 7, driver 5 08:28:31 DEBUG| [ 0.231048494,6] CPU: P9 generation processor (max 4 threads/core) 08:28:31 DEBUG| [ 0.231412547,7] CPU: Boot CPU PIR is 0x0000 PVR is 0x004e1202 08:28:31 DEBUG| [ 0.231857798,7] OPAL table 08:28:31 DEBUG| <-- { "return": { "icount": 5655658, "mode": "record", "filename": "/builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/replay.bin" } } 08:28:31 DEBUG| Shutting down VM appliance; timeout=30 08:28:31 DEBUG| Attempting graceful termination 08:28:31 DEBUG| Closing console socket 08:28:31 DEBUG| Politely asking QEMU to terminate 08:28:31 DEBUG| --> { "execute": "quit" } 08:28:31 DEBUG| <-- { "return": {} } 08:28:31 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 453159 }, "event": "SHUTDOWN", "data": { "guest": false, "reason": "host-qmp-quit" } } 08:28:31 DEBUG| disconnect() called. 08:28:31 DEBUG| Transitioning from 'Runstate.RUNNING' to 'Runstate.DISCONNECTING'. 08:28:31 DEBUG| Scheduling disconnect. 08:28:31 DEBUG| Draining the outbound queue ... 08:28:31 DEBUG| Flushing the StreamWriter ... 08:28:31 DEBUG| Cancelling writer task. 08:28:31 DEBUG| Cancelling reader task. 08:28:31 DEBUG| Waiting for tasks to complete ... 08:28:31 DEBUG| Task.Writer: cancelled. 08:28:31 DEBUG| Task.Writer: exiting. 08:28:31 DEBUG| Task.Reader: cancelled. 08:28:31 DEBUG| Task.Reader: exiting. 08:28:31 DEBUG| Closing StreamWriter. 08:28:31 DEBUG| Waiting for StreamWriter to close ... 08:28:31 DEBUG| StreamWriter closed. 08:28:31 DEBUG| Disconnected. 08:28:31 DEBUG| QMP Disconnected. 08:28:31 DEBUG| Transitioning from 'Runstate.DISCONNECTING' to 'Runstate.IDLE'. 08:28:31 DEBUG| Waiting (timeout=30) for QEMU process (pid=1580) to terminate 08:28:31 DEBUG| Cleaning up after VM process 08:28:31 INFO | recorded log with 5655658+ steps 08:28:31 DEBUG| QEMUMachine "1dfa83ad-c638-4858-b96d-ec21870ab53a" created 08:28:31 DEBUG| QEMUMachine "1dfa83ad-c638-4858-b96d-ec21870ab53a" temp_dir: /builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/qemu-machine-i11yz6dd 08:28:31 DEBUG| QEMUMachine "1dfa83ad-c638-4858-b96d-ec21870ab53a" log_dir: /builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv 08:28:31 INFO | replaying the execution... 08:28:31 DEBUG| Registering . 08:28:31 DEBUG| VM launch command: './qemu-system-ppc64 -display none -vga none -chardev socket,id=mon,fd=5 -mon chardev=mon,mode=control -machine powernv -chardev socket,id=console,fd=19 -serial chardev:console -gdb tcp::21192 -S -icount shift=7,rr=replay,rrfile=/builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/replay.bin,rrsnapshot=init -net none -drive file=/builds/thuth/qemu/build/tests/results/job-2023-11-21T08.18-1c1e081/test-results/tmp_dirvmnrd25o/79-tests_avocado_reverse_debugging.py_ReverseDebugging_ppc64.test_ppc64_powernv/disk.qcow2,if=none' 08:28:31 DEBUG| Transitioning from 'Runstate.IDLE' to 'Runstate.CONNECTING'. 08:28:31 DEBUG| Connecting with existing socket: fd=12, family=, type= 08:28:31 DEBUG| Connected. 08:28:31 DEBUG| Awaiting greeting ... 08:28:31 DEBUG| <-- { "QMP": { "version": { "qemu": { "micro": 90, "minor": 1, "major": 8 }, "package": "v5.2.0-26508-gaf9264da80" }, "capabilities": [ "oob" ] } } 08:28:31 DEBUG| Negotiating capabilities ... 08:28:31 DEBUG| --> { "execute": "qmp_capabilities", "arguments": { "enable": [ "oob" ] } } 08:28:31 DEBUG| <-- { "return": {} } 08:28:31 DEBUG| Transitioning from 'Runstate.CONNECTING' to 'Runstate.RUNNING'. 08:28:31 DEBUG| Opening console socket 08:28:31 INFO | connecting to gdbstub 08:28:31 INFO | stepping forward 08:28:31 INFO | saving position 10 08:28:31 INFO | saving position 14 08:28:31 INFO | saving position 40 08:28:31 INFO | saving position 44 08:28:31 INFO | saving position 3008 08:28:31 INFO | saving position 300c 08:28:31 INFO | saving position 3010 08:28:31 INFO | saving position 3014 08:28:31 INFO | saving position 3018 08:28:31 INFO | saving position 301c 08:28:31 INFO | stepping backward 08:28:31 INFO | found position 301c 08:28:31 INFO | found position 3018 08:28:31 INFO | found position 3014 08:28:31 INFO | found position 3010 08:28:31 INFO | found position 300c 08:28:31 INFO | found position 3008 08:28:31 INFO | found position 44 08:28:31 INFO | found position 40 08:28:32 INFO | found position 14 08:28:32 INFO | found position 10 08:28:32 INFO | stepping forward 08:28:32 INFO | found position 10 08:28:32 INFO | found position 14 08:28:32 INFO | found position 40 08:28:32 INFO | found position 44 08:28:32 INFO | found position 3008 08:28:32 INFO | found position 300c 08:28:32 INFO | found position 3010 08:28:32 INFO | found position 3014 08:28:32 INFO | found position 3018 08:28:32 INFO | found position 301c 08:28:32 INFO | setting breakpoints 08:28:32 INFO | continuing execution 08:28:32 DEBUG| --> { "execute": "replay-break", "arguments": { "icount": 5655657 } } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 630400 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 630738 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 630965 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 631155 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 631438 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 631653 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 631935 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 632127 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 632380 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 632593 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 632858 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 633051 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 633316 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 633517 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 633775 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 633973 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 634247 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 634437 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 634707 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 634910 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 681146 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 681795 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 722346 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 723103 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 764757 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 765468 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 806932 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 807686 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 849868 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 850664 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 892036 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 892734 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 934846 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 935520 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 976442 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555311, "microseconds": 977155 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 29287 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 30093 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 74012 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 74271 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 74873 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 75471 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 75800 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 75987 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 76239 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 76423 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 76666 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 76861 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 77106 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 77321 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 77564 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 77760 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 77987 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 78176 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 78408 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 78598 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 78846 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 79033 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 79267 }, "event": "RESUME" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 79451 }, "event": "STOP" } 08:28:32 DEBUG| <-- { "return": {} } 08:28:32 DEBUG| [ 0.230392217,5] OPAL v7.0 starting... 08:28:32 DEBUG| [ 0.230674939,7] initial console log level: memory 7, driver 5 08:28:32 DEBUG| [ 0.231048494,6] CPU: P9 generation processor (max 4 threads/core) 08:28:32 DEBUG| [ 08:28:32 DEBUG| [ 0.231412547,7] CPU: Boot CPU PIR is 0x0000 PVR is 0x004e1202 08:28:32 DEBUG| [ 08:28:32 ERROR| 08:28:32 ERROR| Reproduced traceback from: /builds/thuth/qemu/build/pyvenv/lib64/python3.8/site-packages/avocado/core/test.py:770 08:28:32 ERROR| Traceback (most recent call last): 08:28:32 ERROR| File "/builds/thuth/qemu/build/tests/avocado/reverse_debugging.py", line 262, in test_ppc64_powernv 08:28:32 ERROR| self.reverse_debugging() 08:28:32 ERROR| File "/builds/thuth/qemu/build/tests/avocado/reverse_debugging.py", line 178, in reverse_debugging 08:28:32 ERROR| g.cmd(b'c') 08:28:32 ERROR| File "/builds/thuth/qemu/build/pyvenv/lib64/python3.8/site-packages/avocado/utils/gdb.py", line 783, in cmd 08:28:32 ERROR| response_payload = self.decode(result) 08:28:32 ERROR| File "/builds/thuth/qemu/build/pyvenv/lib64/python3.8/site-packages/avocado/utils/gdb.py", line 738, in decode 08:28:32 ERROR| raise InvalidPacketError 08:28:32 ERROR| avocado.utils.gdb.InvalidPacketError 08:28:32 ERROR| 08:28:32 DEBUG| Local variables: 08:28:32 DEBUG| -> self : 79-tests/avocado/reverse_debugging.py:ReverseDebugging_ppc64.test_ppc64_powernv 08:28:32 DEBUG| Shutting down VM appliance; timeout=30 08:28:32 DEBUG| Attempting graceful termination 08:28:32 DEBUG| Closing console socket 08:28:32 DEBUG| Politely asking QEMU to terminate 08:28:32 DEBUG| --> { "execute": "quit" } 08:28:32 DEBUG| <-- { "timestamp": { "seconds": 1700555312, "microseconds": 86122 }, "event": "RESUME" } 08:28:32 ERROR| Task.Reader: BrokenPipeError: [Errno 32] Broken pipe 08:28:32 DEBUG| Task.Reader: failure: | Traceback (most recent call last): | File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 870, in _bh_loop_forever | await async_fn() | File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 908, in _bh_recv_message | msg = await self._recv() | File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 1009, in _recv | message = await self._do_recv() | File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 402, in _do_recv | msg_bytes = await self._readline() | File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 973, in _readline | msg_bytes = await self._reader.readline() | File "/usr/lib64/python3.8/asyncio/streams.py", line 540, in readline | line = await self.readuntil(sep) | File "/usr/lib64/python3.8/asyncio/streams.py", line 632, in readuntil | await self._wait_for_data('readuntil') | File "/usr/lib64/python3.8/asyncio/streams.py", line 517, in _wait_for_data | await self._waiter | File "/usr/lib64/python3.8/asyncio/selector_events.py", line 910, in write | n = self._sock.send(data) | BrokenPipeError: [Errno 32] Broken pipe 08:28:32 DEBUG| Transitioning from 'Runstate.RUNNING' to 'Runstate.DISCONNECTING'. 08:28:32 DEBUG| Scheduling disconnect. 08:28:32 DEBUG| Task.Reader: exiting. 08:28:32 DEBUG| Cancelling writer task. 08:28:32 DEBUG| Waiting for tasks to complete ... 08:28:32 DEBUG| Task.Writer: cancelled. 08:28:32 DEBUG| Task.Writer: exiting. 08:28:32 DEBUG| Waiting for StreamWriter to close ... 08:28:32 DEBUG| Discarding Exception from wait_closed: | Traceback (most recent call last): | File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 834, in _bh_close_stream | await wait_closed(self._writer) | File "/builds/thuth/qemu/python/qemu/qmp/util.py", line 130, in wait_closed | await writer.wait_closed() | File "/usr/lib64/python3.8/asyncio/streams.py", line 359, in wait_closed | await self._protocol._get_close_waiter(self) | File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 870, in _bh_loop_forever | await async_fn() | File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 908, in _bh_recv_message | msg = await self._recv() | File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 1009, in _recv | message = await self._do_recv() | File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 402, in _do_recv | msg_bytes = await self._readline() | File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 973, in _readline | msg_bytes = await self._reader.readline() | File "/usr/lib64/python3.8/asyncio/streams.py", line 540, in readline | line = await self.readuntil(sep) | File "/usr/lib64/python3.8/asyncio/streams.py", line 632, in readuntil | await self._wait_for_data('readuntil') | File "/usr/lib64/python3.8/asyncio/streams.py", line 517, in _wait_for_data | await self._waiter | File "/usr/lib64/python3.8/asyncio/selector_events.py", line 910, in write | n = self._sock.send(data) | BrokenPipeError: [Errno 32] Broken pipe 08:28:32 DEBUG| StreamWriter closed. 08:28:32 DEBUG| Disconnected. 08:28:32 DEBUG| Cancelling pending executions 08:28:32 DEBUG| Cancelling execution 'None' 08:28:32 DEBUG| QMP Disconnected. 08:28:32 DEBUG| disconnect() called. 08:28:32 DEBUG| Transitioning from 'Runstate.DISCONNECTING' to 'Runstate.IDLE'. 08:28:32 DEBUG| Graceful shutdown failed Traceback (most recent call last): File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 574, in _soft_shutdown self.qmp('quit') File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 705, in qmp ret = self._qmp.cmd_raw(cmd, args=qmp_args) File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 208, in cmd_raw return self.cmd_obj(qmp_cmd) File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 186, in cmd_obj self._sync( File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 102, in _sync return self._aloop.run_until_complete( File "/usr/lib64/python3.8/asyncio/base_events.py", line 616, in run_until_complete return future.result() File "/usr/lib64/python3.8/asyncio/tasks.py", line 455, in wait_for return await fut File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 547, in _raw return await self._execute(msg, assign_id=assign_id) File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 496, in _execute return await self._reply(exec_id) File "/builds/thuth/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 "/builds/thuth/qemu/python/qemu/machine/machine.py", line 605, in _do_shutdown self._soft_shutdown(timeout) File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 577, in _soft_shutdown self._close_qmp_connection() File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 495, in _close_qmp_connection self._qmp.close() File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 281, in close self._sync( File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 102, in _sync return self._aloop.run_until_complete( File "/usr/lib64/python3.8/asyncio/base_events.py", line 616, in run_until_complete return future.result() File "/usr/lib64/python3.8/asyncio/tasks.py", line 455, in wait_for return await fut File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 399, in disconnect await self._wait_disconnect() File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 719, in _wait_disconnect await all_defined_tasks # Raise Exceptions from the bottom half. File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 834, in _bh_close_stream await wait_closed(self._writer) File "/builds/thuth/qemu/python/qemu/qmp/util.py", line 130, in wait_closed await writer.wait_closed() File "/usr/lib64/python3.8/asyncio/streams.py", line 359, in wait_closed await self._protocol._get_close_waiter(self) File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 870, in _bh_loop_forever await async_fn() File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 908, in _bh_recv_message msg = await self._recv() File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 1009, in _recv message = await self._do_recv() File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 402, in _do_recv msg_bytes = await self._readline() File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 973, in _readline msg_bytes = await self._reader.readline() File "/usr/lib64/python3.8/asyncio/streams.py", line 540, in readline line = await self.readuntil(sep) File "/usr/lib64/python3.8/asyncio/streams.py", line 632, in readuntil await self._wait_for_data('readuntil') File "/usr/lib64/python3.8/asyncio/streams.py", line 517, in _wait_for_data await self._waiter File "/usr/lib64/python3.8/asyncio/selector_events.py", line 910, in write n = self._sock.send(data) BrokenPipeError: [Errno 32] Broken pipe 08:28:32 DEBUG| Falling back to hard shutdown 08:28:32 DEBUG| Performing hard shutdown 08:28:32 DEBUG| Cleaning up after VM process 08:28:32 ERROR| 08:28:32 ERROR| Reproduced traceback from: /builds/thuth/qemu/build/pyvenv/lib64/python3.8/site-packages/avocado/core/test.py:796 08:28:32 ERROR| Traceback (most recent call last): 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 574, in _soft_shutdown 08:28:32 ERROR| self.qmp('quit') 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 705, in qmp 08:28:32 ERROR| ret = self._qmp.cmd_raw(cmd, args=qmp_args) 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 208, in cmd_raw 08:28:32 ERROR| return self.cmd_obj(qmp_cmd) 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 186, in cmd_obj 08:28:32 ERROR| self._sync( 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 102, in _sync 08:28:32 ERROR| return self._aloop.run_until_complete( 08:28:32 ERROR| File "/usr/lib64/python3.8/asyncio/base_events.py", line 616, in run_until_complete 08:28:32 ERROR| return future.result() 08:28:32 ERROR| File "/usr/lib64/python3.8/asyncio/tasks.py", line 455, in wait_for 08:28:32 ERROR| return await fut 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 547, in _raw 08:28:32 ERROR| return await self._execute(msg, assign_id=assign_id) 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 496, in _execute 08:28:32 ERROR| return await self._reply(exec_id) 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 463, in _reply 08:28:32 ERROR| raise result 08:28:32 ERROR| qemu.qmp.qmp_client.ExecInterruptedError: Disconnected 08:28:32 ERROR| 08:28:32 ERROR| During handling of the above exception, another exception occurred: 08:28:32 ERROR| 08:28:32 ERROR| Traceback (most recent call last): 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 605, in _do_shutdown 08:28:32 ERROR| self._soft_shutdown(timeout) 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 577, in _soft_shutdown 08:28:32 ERROR| self._close_qmp_connection() 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 495, in _close_qmp_connection 08:28:32 ERROR| self._qmp.close() 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 281, in close 08:28:32 ERROR| self._sync( 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/qmp/legacy.py", line 102, in _sync 08:28:32 ERROR| return self._aloop.run_until_complete( 08:28:32 ERROR| File "/usr/lib64/python3.8/asyncio/base_events.py", line 616, in run_until_complete 08:28:32 ERROR| return future.result() 08:28:32 ERROR| File "/usr/lib64/python3.8/asyncio/tasks.py", line 455, in wait_for 08:28:32 ERROR| return await fut 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 399, in disconnect 08:28:32 ERROR| await self._wait_disconnect() 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 719, in _wait_disconnect 08:28:32 ERROR| await all_defined_tasks # Raise Exceptions from the bottom half. 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 834, in _bh_close_stream 08:28:32 ERROR| await wait_closed(self._writer) 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/qmp/util.py", line 130, in wait_closed 08:28:32 ERROR| await writer.wait_closed() 08:28:32 ERROR| File "/usr/lib64/python3.8/asyncio/streams.py", line 359, in wait_closed 08:28:32 ERROR| await self._protocol._get_close_waiter(self) 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 870, in _bh_loop_forever 08:28:32 ERROR| await async_fn() 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 908, in _bh_recv_message 08:28:32 ERROR| msg = await self._recv() 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 1009, in _recv 08:28:32 ERROR| message = await self._do_recv() 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/qmp/qmp_client.py", line 402, in _do_recv 08:28:32 ERROR| msg_bytes = await self._readline() 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/qmp/protocol.py", line 973, in _readline 08:28:32 ERROR| msg_bytes = await self._reader.readline() 08:28:32 ERROR| File "/usr/lib64/python3.8/asyncio/streams.py", line 540, in readline 08:28:32 ERROR| line = await self.readuntil(sep) 08:28:32 ERROR| File "/usr/lib64/python3.8/asyncio/streams.py", line 632, in readuntil 08:28:32 ERROR| await self._wait_for_data('readuntil') 08:28:32 ERROR| File "/usr/lib64/python3.8/asyncio/streams.py", line 517, in _wait_for_data 08:28:32 ERROR| await self._waiter 08:28:32 ERROR| File "/usr/lib64/python3.8/asyncio/selector_events.py", line 910, in write 08:28:32 ERROR| n = self._sock.send(data) 08:28:32 ERROR| BrokenPipeError: [Errno 32] Broken pipe 08:28:32 ERROR| 08:28:32 ERROR| The above exception was the direct cause of the following exception: 08:28:32 ERROR| 08:28:32 ERROR| Traceback (most recent call last): 08:28:32 ERROR| File "/builds/thuth/qemu/build/tests/avocado/avocado_qemu/__init__.py", line 384, in tearDown 08:28:32 ERROR| vm.shutdown() 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 642, in shutdown 08:28:32 ERROR| self._do_shutdown(timeout) 08:28:32 ERROR| File "/builds/thuth/qemu/python/qemu/machine/machine.py", line 612, in _do_shutdown 08:28:32 ERROR| raise AbnormalShutdown("Could not perform graceful shutdown") \ 08:28:32 ERROR| qemu.machine.machine.AbnormalShutdown: Could not perform graceful shutdown 08:28:32 ERROR| 08:28:32 DEBUG| DATA (filename=output.expected) => NOT FOUND (data sources: variant, test, file) 08:28:32 DEBUG| DATA (filename=stdout.expected) => NOT FOUND (data sources: variant, test, file) 08:28:32 DEBUG| DATA (filename=stderr.expected) => NOT FOUND (data sources: variant, test, file) 08:28:32 ERROR| Traceback (most recent call last): 08:28:32 ERROR| File "/builds/thuth/qemu/build/pyvenv/lib64/python3.8/site-packages/avocado/core/test.py", line 858, in _run_avocado raise test_exception 08:28:32 ERROR| File "/builds/thuth/qemu/build/pyvenv/lib64/python3.8/site-packages/avocado/core/test.py", line 765, in _run_avocado testMethod() 08:28:32 ERROR| File "/builds/thuth/qemu/build/tests/avocado/reverse_debugging.py", line 262, in test_ppc64_powernv self.reverse_debugging() 08:28:32 ERROR| File "/builds/thuth/qemu/build/tests/avocado/reverse_debugging.py", line 178, in reverse_debugging g.cmd(b'c') 08:28:32 ERROR| File "/builds/thuth/qemu/build/pyvenv/lib64/python3.8/site-packages/avocado/utils/gdb.py", line 783, in cmd response_payload = self.decode(result) 08:28:32 ERROR| File "/builds/thuth/qemu/build/pyvenv/lib64/python3.8/site-packages/avocado/utils/gdb.py", line 738, in decode raise InvalidPacketError 08:28:32 ERROR| avocado.utils.gdb.InvalidPacketError 08:28:32 ERROR| ERROR 79-tests/avocado/reverse_debugging.py:ReverseDebugging_ppc64.test_ppc64_powernv -> InvalidPacketError: 08:28:32 INFO | ```