ReplayKernelNormal.test_mips_malta functional test timeouting

[Philippe Mathieu-Daudé]

Hi Pavel,

The "normal" test_mips_malta timeouted on acceptance-system-fedora job:

 (23/36)
tests/acceptance/replay_kernel.py:ReplayKernelNormal.test_mips_malta:
INTERRUPTED: Test interrupted by SIGTERM\nRunner error occurred: Timeout
reached\nOriginal status: ERROR\n{'name':
'23-tests/acceptance/replay_kernel.py:ReplayKernelNormal.test_mips_malta',
'logdir':
'/builds/philmd/qemu2/build/tests/results/job-2021-03-19T09.38-e5751b5/...
(120.52 s)

artifact's debug.log:

09:43:04 DEBUG| PARAMS (key=arch, path=*, default=mips) => 'mips'
09:43:04 DEBUG| PARAMS (key=machine, path=*, default=malta) => 'malta'
09:43:04 DEBUG| PARAMS (key=qemu_bin, path=*,
default=./qemu-system-mips) => './qemu-system-mips'
09:43:04 INFO | Running 'ar t
/builds/philmd/qemu2/avocado-cache/by_location/44bac84408e676508a64ecba77e99389ac8fe10d/linux-image-2.6.32-5-4kc-malta_2.6.32-48_mips.deb'
09:43:04 DEBUG| [stdout] debian-binary
09:43:04 INFO | Command 'ar t
/builds/philmd/qemu2/avocado-cache/by_location/44bac84408e676508a64ecba77e99389ac8fe10d/linux-image-2.6.32-5-4kc-malta_2.6.32-48_mips.deb'
finished with 0 after 0.0019164085388183594s
09:43:04 DEBUG| [stdout] control.tar.gz
09:43:04 DEBUG| [stdout] data.tar.gz
09:43:04 INFO | Running 'ar x
/builds/philmd/qemu2/avocado-cache/by_location/44bac84408e676508a64ecba77e99389ac8fe10d/linux-image-2.6.32-5-4kc-malta_2.6.32-48_mips.deb
data.tar.gz'
09:43:04 INFO | Command 'ar x
/builds/philmd/qemu2/avocado-cache/by_location/44bac84408e676508a64ecba77e99389ac8fe10d/linux-image-2.6.32-5-4kc-malta_2.6.32-48_mips.deb
data.tar.gz' finished with 0 after 0.047913551330566406s
09:43:05 INFO | recording the execution...
09:43:05 DEBUG| VM launch command: './qemu-system-mips -display none
-vga none -chardev
socket,id=mon,path=/var/tmp/avo_qemu_sock_z2x1qvna/qemu-601-monitor.sock
-mon chardev=mon,mode=control -machine malta -chardev
socket,id=console,path=/var/tmp/avo_qemu_sock_z2x1qvna/qemu-601-console.sock,server=on,wait=off
-serial chardev:console -icount
shift=5,rr=record,rrfile=/var/tmp/avocado__uxji4xt/avocado_job_j3sdjxv9/23-tests_acceptance_replay_kernel.py_ReplayKernelNormal.test_mips_malta/replay.bin
-kernel
/var/tmp/avocado__uxji4xt/avocado_job_j3sdjxv9/23-tests_acceptance_replay_kernel.py_ReplayKernelNormal.test_mips_malta/boot/vmlinux-2.6.32-5-4kc-malta
-append printk.time=1 panic=-1 console=ttyS0 -net none -no-reboot'
09:43:05 DEBUG| >>> {'execute': 'qmp_capabilities'}
09:43:05 DEBUG| <<< {'return': {}}
09:43:05 DEBUG| [    0.000000] Initrd not found or empty - disabling initrd
09:43:05 DEBUG| [    0.000000] Zone PFN ranges:
09:43:05 DEBUG| [    0.000000]   DMA      0x00000000 -> 0x00001000
09:43:05 DEBUG| [    0.000000]   Normal   0x00001000 -> 0x00007fff
09:43:05 DEBUG| [    0.000000] Movable zone start PFN for each node
09:43:05 DEBUG| [    0.000000] early_node_map[1] active PFN ranges
09:43:05 DEBUG| [    0.000000]     0: 0x00000000 -> 0x00007fff
09:43:05 DEBUG| [    0.000000] Built 1 zonelists in Zone order, mobility
grouping on.  Total pages: 32511
09:43:05 DEBUG| [    0.000000] Kernel command line: printk.time=1
panic=-1 console=ttyS0
09:43:05 DEBUG| >>> {'execute': 'quit'}
09:43:05 DEBUG| <<< {'return': {}}
09:43:05 INFO | finished the recording with log size 21979 bytes
09:43:05 INFO | elapsed time 0.13 sec
09:43:05 INFO | replaying the execution...
09:43:05 DEBUG| VM launch command: './qemu-system-mips -display none
-vga none -chardev
socket,id=mon,path=/var/tmp/avo_qemu_sock_opalepcn/qemu-601-monitor.sock
-mon chardev=mon,mode=control -machine malta -chardev
socket,id=console,path=/var/tmp/avo_qemu_sock_opalepcn/qemu-601-console.sock,server=on,wait=off
-serial chardev:console -icount
shift=5,rr=replay,rrfile=/var/tmp/avocado__uxji4xt/avocado_job_j3sdjxv9/23-tests_acceptance_replay_kernel.py_ReplayKernelNormal.test_mips_malta/replay.bin
-kernel
/var/tmp/avocado__uxji4xt/avocado_job_j3sdjxv9/23-tests_acceptance_replay_kernel.py_ReplayKernelNormal.test_mips_malta/boot/vmlinux-2.6.32-5-4kc-malta
-append printk.time=1 panic=-1 console=ttyS0 -net none -no-reboot'
09:43:05 DEBUG| >>> {'execute': 'qmp_capabilities'}
09:43:05 DEBUG| <<< {'return': {}}
09:43:06 DEBUG| [    0.000000] Initrd not found or empty - disabling initrd
09:43:06 DEBUG| [    0.000000] Zone PFN ranges:
09:43:06 DEBUG| [    0.000000]   DMA      0x00000000 -> 0x00001000
09:43:06 DEBUG| [    0.000000]   Normal   0x00001000 -> 0x00007fff
09:43:06 DEBUG| [    0.000000] Movable zone start PFN for each node
09:43:06 DEBUG| [    0.000000] early_node_map[1] active PFN ranges
09:43:06 DEBUG| [    0.000000]
09:45:05 ERROR|
09:45:05 ERROR| Reproduced traceback from:
/builds/philmd/qemu2/build/tests/venv/lib64/python3.9/site-packages/avocado/core/test.py:767
09:45:05 ERROR| Traceback (most recent call last):
09:45:05 ERROR|   File
"/builds/philmd/qemu2/build/tests/acceptance/replay_kernel.py", line
114, in test_mips_malta
09:45:05 ERROR|     self.run_rr(kernel_path, kernel_command_line,
console_pattern, shift=5)
09:45:05 ERROR|   File
"/builds/philmd/qemu2/build/tests/acceptance/replay_kernel.py", line 75,
in run_rr
09:45:05 ERROR|     t2 = self.run_vm(kernel_path, kernel_command_line,
console_pattern,
09:45:05 ERROR|   File
"/builds/philmd/qemu2/build/tests/acceptance/replay_kernel.py", line 58,
in run_vm
09:45:05 ERROR|     self.wait_for_console_pattern(console_pattern, vm)
09:45:05 ERROR|   File
"/builds/philmd/qemu2/build/tests/acceptance/boot_linux_console.py",
line 52, in wait_for_console_pattern
09:45:05 ERROR|     wait_for_console_pattern(self, success_message,
09:45:05 ERROR|   File
"/builds/philmd/qemu2/build/tests/acceptance/avocado_qemu/__init__.py",
line 140, in wait_for_console_pattern
09:45:05 ERROR|     _console_interaction(test, success_message,
failure_message, None, vm=vm)
09:45:05 ERROR|   File
"/builds/philmd/qemu2/build/tests/acceptance/avocado_qemu/__init__.py",
line 92, in _console_interaction
09:45:05 ERROR|     msg = console.readline().strip()
09:45:05 ERROR|   File "/usr/lib64/python3.9/socket.py", line 704, in
readinto
09:45:05 ERROR|     return self._sock.recv_into(b)
09:45:05 ERROR|   File
"/builds/philmd/qemu2/build/tests/venv/lib64/python3.9/site-packages/avocado/plugins/runner.py",
line 77, in sigterm_handler
09:45:05 ERROR|     raise RuntimeError("Test interrupted by SIGTERM")
09:45:05 ERROR| RuntimeError: Test interrupted by SIGTERM

What to do, simply implement the timeout again?
Allow failure?

Thanks,

Phil.