The avocado test replay_kernel.py:ReplayKernelNormal.test_x86_64_pc is unreliable
Host environment
- Operating system: Debian Bookworm
- OS/kernel version: Linux draig 6.1.0-13-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.1.55-1 (2023-09-29) x86_64 GNU/Linux
- Architecture: x86_64
- QEMU flavor: qemu-system-x86_64
- QEMU version: 8.2-rc2
- QEMU command line:
env QEMU_TEST_FLAKY_TESTS=1 ./pyvenv/bin/avocado run tests/avocado/replay_kernel.py:ReplayKernelNormal.test_x86_64_pc
Emulated/Virtualized environment
- Operating system: Linux
- OS/kernel version: 4.18.16-300.fc29.x86_64
- Architecture: x86_64
Description of problem
The replay test case is unreliable and often hangs at the second stage
Additional information
The record stage complete fine:
2023-11-30 17:25:27,944 protocol L0481 DEBUG| Transitioning from 'Runstate.CONNECTING' to 'Runstate.RUNNING'.
2023-11-30 17:25:27,944 machine L0925 DEBUG| Opening console file
2023-11-30 17:25:27,944 machine L0903 DEBUG| Opening console socket
2023-11-30 17:25:42,652 __init__ L0153 DEBUG| [ 0.000000] Linux version 4.18.16-300.fc29.x86_64 (mockbuild@bkernel04.phx2.fedoraproject.org) (gcc version 8.2.1 20
180801 (Red Hat 8.2.1-2) (GCC)) #1 SMP Sat Oct 20 23:24:08 UTC 2018
2023-11-30 17:25:42,652 __init__ L0153 DEBUG| [ 0.000000] Command line: printk.time=1 panic=-1 console=ttyS0
2023-11-30 17:25:42,652 __init__ L0153 DEBUG| [ 0.000000] x86/fpu: x87 FPU will use FXSAVE
2023-11-30 17:25:42,652 __init__ L0153 DEBUG| [ 0.000000] BIOS-provided physical RAM map:
2023-11-30 17:25:42,653 __init__ L0153 DEBUG| [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
2023-11-30 17:25:42,653 __init__ L0153 DEBUG| [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
2023-11-30 17:25:42,653 __init__ L0153 DEBUG| [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
2023-11-30 17:25:42,653 __init__ L0153 DEBUG| [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x0000000007fdffff] usable
2023-11-30 17:25:42,653 __init__ L0153 DEBUG| [ 0.000000] BIOS-e820: [mem 0x0000000007fe0000-0x0000000007ffffff] reserved
2023-11-30 17:25:42,653 __init__ L0153 DEBUG| [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
2023-11-30 17:25:42,653 __init__ L0153 DEBUG| [ 0.000000] BIOS-e820: [mem 0x000000fd00000000-0x000000ffffffffff] reserved
2023-11-30 17:25:42,653 __init__ L0153 DEBUG| [ 0.000000] NX (Execute Disable) protection: active
2023-11-30 17:25:42,653 __init__ L0153 DEBUG| [ 0.000000] SMBIOS 3.0.0 present.
2023-11-30 17:25:42,653 __init__ L0153 DEBUG| [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/01/201
4
2023-11-30 17:25:42,653 __init__ L0153 DEBUG| [ 0.000000] last_pfn = 0x7fe0 max_arch_pfn = 0x400000000
2023-11-30 17:25:42,653 __init__ L0153 DEBUG| [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT
2023-11-30 17:25:42,653 __init__ L0153 DEBUG| [ 0.000000] found SMP MP-table at [mem 0x000f5480-0x000f548f] mapped at [(____ptrval____)]
2023-11-30 17:25:42,654 __init__ L0153 DEBUG| [ 0.000000] ACPI: Early table checksum verification disabled
2023-11-30 17:25:42,654 __init__ L0153 DEBUG| [ 0.000000] ACPI: RSDP 0x00000000000F52A0 000014 (v00 BOCHS )
2023-11-30 17:25:42,654 __init__ L0153 DEBUG| [ 0.000000] ACPI: RSDT 0x0000000007FE1C78 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001)
2023-11-30 17:25:42,654 __init__ L0153 DEBUG| [ 0.000000] ACPI: FACP 0x0000000007FE1B2C 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001)
2023-11-30 17:25:42,654 __init__ L0153 DEBUG| [ 0.000000] ACPI: DSDT 0x0000000007FE0040 001AEC (v01 BOCHS BXPC 00000001 BXPC 00000001)
2023-11-30 17:25:42,654 __init__ L0153 DEBUG| [ 0.000000] ACPI: FACS 0x0000000007FE0000 000040
2023-11-30 17:25:42,654 __init__ L0153 DEBUG| [ 0.000000] ACPI: APIC 0x0000000007FE1BA0 000078 (v03 BOCHS BXPC 00000001 BXPC 00000001)
2023-11-30 17:25:42,654 __init__ L0153 DEBUG| [ 0.000000] ACPI: HPET 0x0000000007FE1C18 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001)
2023-11-30 17:25:42,654 __init__ L0153 DEBUG| [ 0.000000] ACPI: WAET 0x0000000007FE1C50 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001)
2023-11-30 17:25:42,654 __init__ L0153 DEBUG| [ 0.000000] No NUMA configuration found
...
After recording the initial step the replay hangs shortly after mapping the BIOS until the test timeout terminates it.
2023-11-30 17:25:59,414 __init__ L0153 DEBUG| [ 0.000000] Linux version 4.18.16-300.fc29.x86_64 (mockbuild@bkernel04.phx2.fedoraproject.org) (gcc version 8.2.1 20180801 (Red Hat 8.2.1-2) (GCC)) #1 SMP Sat Oct 20 23:24:08 UTC 2018
2023-11-30 17:25:59,415 __init__ L0153 DEBUG| [ 0.000000] Command line: printk.time=1 panic=-1 console=ttyS0
2023-11-30 17:25:59,415 __init__ L0153 DEBUG| [ 0.000000] x86/fpu: x87 FPU will use FXSAVE
2023-11-30 17:25:59,415 __init__ L0153 DEBUG| [ 0.000000] BIOS-provided physical RAM map:
2023-11-30 17:25:59,416 __init__ L0153 DEBUG| [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
2023-11-30 17:25:59,416 __init__ L0153 DEBUG| [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
2023-11-30 17:25:59,420 __init__ L0153 DEBUG| [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] re
2023-11-30 17:27:28,826 stacktrace L0039 ERROR|
2023-11-30 17:27:28,826 stacktrace L0041 ERROR| Reproduced traceback from: /home/alex/lsrc/qemu.git/builds/all/pyvenv/lib/python3.11/site-packages/avocado/core/test.py:770
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| Traceback (most recent call last):
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| File "/home/alex/lsrc/qemu.git/builds/all/pyvenv/lib/python3.11/site-packages/avocado/core/decorators.py", line 90, in wrapper
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| return function(obj, *args, **kwargs)
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| File "/home/alex/lsrc/qemu.git/builds/all/tests/avocado/replay_kernel.py", line 101, in test_x86_64_pc
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| self.run_rr(kernel_path, kernel_command_line, console_pattern, shift=5)
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| File "/home/alex/lsrc/qemu.git/builds/all/tests/avocado/replay_kernel.py", line 78, in run_rr
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| t2 = self.run_vm(kernel_path, kernel_command_line, console_pattern,
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| File "/home/alex/lsrc/qemu.git/builds/all/tests/avocado/replay_kernel.py", line 61, in run_vm
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| self.wait_for_console_pattern(console_pattern, vm)
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| File "/home/alex/lsrc/qemu.git/builds/all/tests/avocado/boot_linux_console.py", line 52, in wait_for_console_pattern
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| wait_for_console_pattern(self, success_message,
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| File "/home/alex/lsrc/qemu.git/builds/all/tests/avocado/avocado_qemu/__init__.py", line 199, in wait_for_console_pattern
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| _console_interaction(test, success_message, failure_message, None, vm=vm)
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| File "/home/alex/lsrc/qemu.git/builds/all/tests/avocado/avocado_qemu/__init__.py", line 148, in _console_interaction
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| msg = console.readline().decode().strip()
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| ^^^^^^^^^^^^^^^^^^
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| File "/usr/lib/python3.11/socket.py", line 706, in readinto
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| return self._sock.recv_into(b)
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| ^^^^^^^^^^^^^^^^^^^^^^^
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| File "/home/alex/lsrc/qemu.git/builds/all/pyvenv/lib/python3.11/site-packages/avocado/plugins/runner.py", line 77, in sigterm_handler
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| raise RuntimeError("Test interrupted by SIGTERM")
2023-11-30 17:27:28,827 stacktrace L0045 ERROR| RuntimeError: Test interrupted by SIGTERM
2023-11-30 17:27:28,827 stacktrace L0046 ERROR|
Edited by Alex Bennée