Re: tests/avocado/replay_kernel: ReplayKernelNormal.test_aarch64_virt failing

2023-07-11 Thread John Snow 
On Tue, Jul 11, 2023, 12:43 AM Pavel Dovgalyuk 
wrote:

> On 10.07.2023 20:14, Philippe Mathieu-Daudé wrote:
> > Hi,
> >
> > Per tests/avocado/replay_kernel.py:
> >
> >  def test_aarch64_virt(self):
> >  ...
> >  console_pattern = 'VFS: Cannot open root device'
> >
> > the test is succeeding, but Avocado reports an error.
>
> Does the emulator exit when error "Cannot open root device" happens?
> Therefore 'quit' command can't be processed in this case.
>
> >
> > I could get a verbose debug.log, so sharing it here, enjoy!
> >
> > Regards,
> >
> > Phil.
>

Yep, this is a race condition on cleanup.

The machine/qmp libraries will throw an exception if they can't exit
cleanly, which is by design to catch QEMU crashes on the exit/teardown path.

If the test expects the QEMU process to exit voluntarily without being
issued 'quit' via QMP, you should use vm.wait() instead of vm.shutdown().

It looks like the QMP library is getting a SHUTDOWN event for which the
reason is "guest-reset". The socket dies and the VM management code
ultimately reports that it wasn't able to shut the guest down cleanly
because it went away unexpectedly, which is true.

(Sorry the traceback is so verbose - perils of asyncio and accidentally
losing debug information means you see a bunch of traces that look almost
identical as they're handled and reported from the backend to the frontend,
then re-contextualized for each library it bubbles up through. Winds up
looking gnarly but it does give incredibly rich detail for the crash, so
thanks for uploading the log! These failures used to crash silently with no
info whatsoever.)

--js

Re: tests/avocado/replay_kernel: ReplayKernelNormal.test_aarch64_virt failing

2023-07-10 Thread Pavel Dovgalyuk 

On 10.07.2023 20:14, Philippe Mathieu-Daudé wrote:

Hi,

Per tests/avocado/replay_kernel.py:

     def test_aarch64_virt(self):
     ...
     console_pattern = 'VFS: Cannot open root device'

the test is succeeding, but Avocado reports an error.


Does the emulator exit when error "Cannot open root device" happens?
Therefore 'quit' command can't be processed in this case.



I could get a verbose debug.log, so sharing it here, enjoy!

Regards,

Phil.

tests/avocado/replay_kernel: ReplayKernelNormal.test_aarch64_virt failing

2023-07-10 Thread Philippe Mathieu-Daudé 

Hi,

Per tests/avocado/replay_kernel.py:

def test_aarch64_virt(self):
...
console_pattern = 'VFS: Cannot open root device'

the test is succeeding, but Avocado reports an error.

I could get a verbose debug.log, so sharing it here, enjoy!

Regards,

Phil.[stdlog] 2023-07-10 19:04:08,084 avocado.test INFO | INIT 
1-tests/avocado/replay_kernel.py:ReplayKernelNormal.test_aarch64_virt
[stdlog] 2023-07-10 19:04:08,089 avocado.test DEBUG| PARAMS (key=timeout, 
path=*, default=120) => 120
[stdlog] 2023-07-10 19:04:08,090 avocado.test DEBUG| Test metadata:
[stdlog] 2023-07-10 19:04:08,091 avocado.test DEBUG|   filename: 
/Users/philmd/build/tests/avocado/replay_kernel.py
[stdlog] 2023-07-10 19:04:08,092 avocado.test DEBUG|   teststmpdir: 
/var/folders/yj/r7khncsj4d77k04ybz9lw4tmgn/T/avocado_0mpq0qad
[stdlog] 2023-07-10 19:04:08,095 avocado.test INFO | START 
1-tests/avocado/replay_kernel.py:ReplayKernelNormal.test_aarch64_virt
[stdlog] 2023-07-10 19:04:08,095 avocado.test DEBUG| PARAMS (key=arch, path=*, 
default=aarch64) => 'aarch64'
[stdlog] 2023-07-10 19:04:08,096 avocado.test DEBUG| PARAMS (key=cpu, path=*, 
default=cortex-a53) => 'cortex-a53'
[stdlog] 2023-07-10 19:04:08,096 avocado.test DEBUG| PARAMS (key=qemu_bin, 
path=*, default=./qemu-system-aarch64) => './qemu-system-aarch64'
[stdlog] 2023-07-10 19:04:08,097 avocado.test DEBUG| PARAMS (key=machine, 
path=*, default=virt) => 'virt'
[stdlog] 2023-07-10 19:04:08,098 avocado.utils.asset INFO | Fetching asset 
https://archives.fedoraproject.org/pub/archive/fedora/linux/releases/29/Everything/aarch64/os/images/pxeboot/vmlinuz
[stdlog] 2023-07-10 19:04:08,115 avocado.utils.asset INFO | Asset already 
exists in cache.
[stdlog] 2023-07-10 19:04:08,117 avocado.test DEBUG| Test workdir initialized 
at: 
/Users/philmd/build/tests/results/job-2023-07-10T19.03-fe8fa79/test-results/170-tests_avocado_replay_kernel.py_ReplayKernelNormal.test_aarch64_virt/tmp_dirucu13g97/1-tests_avocado_replay_kernel.py_ReplayKernelNormal.test_aarch64_virt
[stdlog] 2023-07-10 19:04:08,162 avocado.test DEBUG| QEMUMachine 
"6b877b41-8a16-4f91-acd6-f561ea0a3bcd" created
[stdlog] 2023-07-10 19:04:08,165 avocado.test DEBUG| QEMUMachine 
"6b877b41-8a16-4f91-acd6-f561ea0a3bcd" temp_dir: 
/Users/philmd/build/tests/results/job-2023-07-10T19.03-fe8fa79/test-results/170-tests_avocado_replay_kernel.py_ReplayKernelNormal.test_aarch64_virt/tmp_dirucu13g97/1-tests_avocado_replay_kernel.py_ReplayKernelNormal.test_aarch64_virt/qemu-machine-f4z4lx6_
[stdlog] 2023-07-10 19:04:08,167 avocado.test DEBUG| QEMUMachine 
"6b877b41-8a16-4f91-acd6-f561ea0a3bcd" log_dir: 
/Users/philmd/build/tests/results/job-2023-07-10T19.03-fe8fa79/test-results/170-tests_avocado_replay_kernel.py_ReplayKernelNormal.test_aarch64_virt
[stdlog] 2023-07-10 19:04:08,167 replay INFO | recording the execution...
[stdlog] 2023-07-10 19:04:08,169 qemu.qmp.qmp_client.101e41690 DEBUG| 
Registering .
[stdlog] 2023-07-10 19:04:08,170 asyncio DEBUG| Using selector: KqueueSelector
[stdlog] 2023-07-10 19:04:08,170 qemu.machine.machine DEBUG| VM launch command: 
'./qemu-system-aarch64 -display none -vga none -chardev socket,id=mon,fd=11 
-mon chardev=mon,mode=control -machine virt -chardev 
socket,id=console,path=/var/folders/yj/r7khncsj4d77k04ybz9lw4tmgn/T/qemu_iu7icxth/101e41690.con,server=on,wait=off
 -serial chardev:console -cpu cortex-a53 -icount 
shift=7,rr=record,rrfile=/Users/philmd/build/tests/results/job-2023-07-10T19.03-fe8fa79/test-results/170-tests_avocado_replay_kernel.py_ReplayKernelNormal.test_aarch64_virt/tmp_dirucu13g97/1-tests_avocado_replay_kernel.py_ReplayKernelNormal.test_aarch64_virt/replay.bin
 -kernel 
/Users/philmd/avocado/data/cache/by_location/a00ac4ae676ef0322126abd2f7d38f50cc9cbc95/vmlinuz
 -append printk.time=1 panic=-1 console=ttyAMA0 -net none -no-reboot'
[stdlog] 2023-07-10 19:04:08,183 qemu.qmp.qmp_client.101e41690 DEBUG| 
Transitioning from 'Runstate.IDLE' to 'Runstate.CONNECTING'.
[stdlog] 2023-07-10 19:04:08,187 qemu.qmp.qmp_client.101e41690 DEBUG| 
Connecting with existing socket: fd=12, family=, 
type=
[stdlog] 2023-07-10 19:04:08,191 qemu.qmp.qmp_client.101e41690 DEBUG| Connected.
[stdlog] 2023-07-10 19:04:08,191 qemu.qmp.qmp_client.101e41690 DEBUG| Awaiting 
greeting ...
[stdlog] 2023-07-10 19:04:08,208 qemu.qmp.qmp_client.101e41690 DEBUG| <-- {
[stdlog]   "QMP": {
[stdlog] "version": {
[stdlog]   "qemu": {
[stdlog] "micro": 50,
[stdlog] "minor": 0,
[stdlog] "major": 8
[stdlog]   },
[stdlog]   "package": "v8.0.0-2542-g2268e7980c"
[stdlog] },
[stdlog] "capabilities": [
[stdlog]   "oob"
[stdlog] ]
[stdlog]   }
[stdlog] }
[stdlog] 2023-07-10 19:04:08,209 qemu.qmp.qmp_client.101e41690 DEBUG| 
Negotiating capabilities ...
[stdlog] 2023-07-10 19:04:08,209 qemu.qmp.qmp_client.101e41690 DEBUG| --> {
[stdlog]   "execute": "qmp_capabilities",
[stdlog]   "arguments": {
[stdlog] "enable": [
[stdlog]   "oob"
[stdlog] ]