Re: [PULL 09/14] qmp: Move dispatcher to a coroutine

[Philippe Mathieu-Daudé]

On 10/12/20 1:25 PM, Kevin Wolf wrote:
> Am 12.10.2020 um 12:47 hat Alex Bennée geschrieben:
> > Markus Armbruster <armbru@redhat.com> writes:
> >
> > > From: Kevin Wolf <kwolf@redhat.com>
> > >
> > > This moves the QMP dispatcher to a coroutine and runs all QMP command
> > > handlers that declare 'coroutine': true in coroutine context so they
> > > can avoid blocking the main loop while doing I/O or waiting for other
> > > events.
> >
> > This subtly changes the replay behaviour leading to a hang in:
> >
> >    10:55:18 [alex.bennee@hackbox2:~/l/q/b/bisect] (625581c2…)|✚1(+1/-1) + 
> > ./tests/venv/bin/avocado run 
> > tests/acceptance/replay_kernel.py:ReplayKernel.test_arm_virt
> >    Fetching asset from 
> > tests/acceptance/replay_kernel.py:ReplayKernel.test_arm_virt
> >    JOB ID     : ec11fd2544f06e6c0d421f16afa757b49f7ed734
> >    JOB LOG    : 
> > /home/alex.bennee/avocado/job-results/job-2020-10-12T11.40-ec11fd2/job.log
> >     (1/1) tests/acceptance/replay_kernel.py:ReplayKernel.test_arm_virt: ERROR: 
> > Could not perform graceful shutdown (26.27 s)
> >    RESULTS    : PASS 0 | ERROR 1 | FAIL 0 | SKIP 0 | WARN 0 | INTERRUPT 0 | 
> > CANCEL 0
> >    JOB TIME   : 27.77 s
> >
> > Looking at the log:
> >
> >    2020-10-12 11:40:31,426 __init__         L0085 DEBUG| [    3.887411] 
> > rtc-pl031 9010000.pl031: setting system clock to 2020-10-12 10:40:31 UTC 
> > (1602499231)
> >    2020-10-12 11:40:31,428 __init__         L0085 DEBUG| [    3.887431] 
> > sr_init: No PMIC hook to init smartreflex
> >    2020-10-12 11:40:31,447 __init__         L0085 DEBUG| [    3.897193] 
> > uart-pl011 9000000.pl011: no DMA platform data
> >    2020-10-12 11:40:31,460 __init__         L0085 DEBUG| [    3.897242] md: 
> > Waiting for all devices to be available before autodetect
> >    2020-10-12 11:40:31,462 __init__         L0085 DEBUG| [    3.897259] md: If 
> > you don't use raid, use raid=noautodetect
> >    2020-10-12 11:40:31,475 __init__         L0085 DEBUG| [    3.897819] md: 
> > Autodetecting RAID arrays.
> >    2020-10-12 11:40:31,476 __init__         L0085 DEBUG| [    3.897832] md: 
> > autorun ...
> >    2020-10-12 11:40:31,477 __init__         L0085 DEBUG| [    3.897842] md: ... 
> > autorun DONE.
> >    2020-10-12 11:40:31,483 __init__         L0085 DEBUG| [    3.897962] VFS: Cannot open 
> > root device "(null)" or unknown-block(0,0): error -6
> >    2020-10-12 11:40:31,483 qmp              L0245 DEBUG| >>> {'execute': 'quit'}
> >    2020-10-12 11:40:31,495 qmp              L0145 DEBUG| <<< {'timestamp': 
> > {'seconds': 1602499231, 'microseconds': 493379}, 'event': 'SHUTDOWN', 'data': {'guest': 
> > True, 'reason': 'guest-reset'}}
> >    2020-10-12 11:40:31,733 machine          L0325 WARNI| qemu received signal 6; command: 
> > "./qemu-system-arm -display none -vga none -chardev 
> > socket,id=mon,path=/var/tmp/tmpzls53khe/qemu-8487-monitor.sock -mon 
> > chardev=mon,mode=control -machine virt -chardev 
> > socket,id=console,path=/var/tmp/tmpzls53khe/qemu-8487-console.sock,server,nowait -serial 
> > chardev:console -icount 
> > shift=1,rr=record,rrfile=/var/tmp/avocado_n00stdrf/avocado_job_aw60qdul/1-tests_acceptance_replay_kernel.py_ReplayKernel.test_arm_virt/replay.bin
> >  -kernel 
> > /home/alex.bennee/avocado/data/cache/by_location/62750ce9e069e69e6a7ff04ff54c382ee660b92a/vmlinuz
> >  -append printk.time=1 panic=-1 console=ttyAMA0 -net none -no-reboot"
>
> This looks like a crash (SIGABRT) rather than a hang. Do you have a
> stack trace for the crashed process?

No crash, exit(0):

VFS: Cannot open root device "(null)" or unknown-block(0,0): error -6
Please append a correct "root=" boot option; here are the available 
partitions:
Kernel panic - not syncing: VFS: Unable to mount root fs on 
unknown-block(0,0)
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.16-300.fc29.armv7hl #1
Hardware name: Generic DT based system
[<c0313f7c>] (unwind_backtrace) from [<c030dc64>] (show_stack+0x20/0x24)
[<c030dc64>] (show_stack) from [<c0b50ec4>] (dump_stack+0x88/0xa8)
[<c0b50ec4>] (dump_stack) from [<c03592f8>] (panic+0xd4/0x26c)
[<c03592f8>] (panic) from [<c110183c>] (mount_block_root+0x250/0x2ec)
[<c110183c>] (mount_block_root) from [<c1101950>] (mount_root+0x78/0x90)
[<c1101950>] (mount_root) from [<c1101ac4>] (prepare_namespace+0x15c/0x19c)
[<c1101ac4>] (prepare_namespace) from [<c11012e8>] 
(kernel_init_freeable+0x2c0/0x370)
[<c11012e8>] (kernel_init_freeable) from [<c0b63914>] 
(kernel_init+0x18/0x128)
[<c0b63914>] (kernel_init) from [<c03010e8>] (ret_from_fork+0x14/0x2c)
Exception stack(0xc790bfb0 to 0xc790bff8)
bfa0:                                     00000000 00000000 00000000 
00000000
bfc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 
00000000
bfe0: 00000000 00000000 00000000 00000000 00000013 00000000

-> PSCI call
   -> QEMU_PSCI_0_2_FN_SYSTEM_RESET
      -> SHUTDOWN_CAUSE_GUEST_RESET
         -> exit(0)

> Kevin
>
> >    2020-10-12 11:40:31,734 stacktrace       L0039 ERROR|
> >    2020-10-12 11:40:31,734 stacktrace       L0042 ERROR| Reproduced traceback 
> > from: 
> > /home/alex.bennee/lsrc/qemu.git/builds/bisect/tests/venv/lib/python3.6/site-packages/avocado/core/test.py:767
> >    2020-10-12 11:40:31,735 stacktrace       L0045 ERROR| Traceback (most recent 
> > call last):
> >    2020-10-12 11:40:31,735 stacktrace       L0045 ERROR|   File 
> > "/home/alex.bennee/lsrc/qemu.git/python/qemu/machine.py", line 435, in 
> > _do_shutdown
> >    2020-10-12 11:40:31,735 stacktrace       L0045 ERROR|     
> > self._soft_shutdown(timeout, has_quit)
> >    2020-10-12 11:40:31,735 stacktrace       L0045 ERROR|   File 
> > "/home/alex.bennee/lsrc/qemu.git/python/qemu/machine.py", line 415, in 
> > _soft_shutdown
> >    2020-10-12 11:40:31,735 stacktrace       L0045 ERROR|     
> > self._qmp.cmd('quit')
> >    2020-10-12 11:40:31,735 stacktrace       L0045 ERROR|   File 
> > "/home/alex.bennee/lsrc/qemu.git/python/qemu/qmp.py", line 266, in cmd
> >    2020-10-12 11:40:31,735 stacktrace       L0045 ERROR|     return 
> > self.cmd_obj(qmp_cmd)
> >    2020-10-12 11:40:31,735 stacktrace       L0045 ERROR|   File 
> > "/home/alex.bennee/lsrc/qemu.git/python/qemu/qmp.py", line 249, in cmd_obj
> >    2020-10-12 11:40:31,736 stacktrace       L0045 ERROR|     raise 
> > QMPConnectError("Unexpected empty reply from server")
> >    2020-10-12 11:40:31,736 stacktrace       L0045 ERROR| 
> > qemu.qmp.QMPConnectError: Unexpected empty reply from server
> >    2020-10-12 11:40:31,736 stacktrace       L0045 ERROR|
> >    2020-10-12 11:40:31,736 stacktrace       L0045 ERROR| The above exception 
> > was the direct cause of the following exception:
> >    2020-10-12 11:40:31,736 stacktrace       L0045 ERROR|
> >    2020-10-12 11:40:31,736 stacktrace       L0045 ERROR| Traceback (most recent 
> > call last):
> >    2020-10-12 11:40:31,736 stacktrace       L0045 ERROR|   File 
> > "/home/alex.bennee/lsrc/qemu.git/builds/bisect/tests/acceptance/replay_kernel.py",
> >  line 128, in test_arm_virt
> >    2020-10-12 11:40:31,736 stacktrace       L0045 ERROR|     
> > self.run_rr(kernel_path, kernel_command_line, console_pattern, shift=1)
> >    2020-10-12 11:40:31,736 stacktrace       L0045 ERROR|   File 
> > "/home/alex.bennee/lsrc/qemu.git/builds/bisect/tests/acceptance/replay_kernel.py",
> >  line 71, in run_rr
> >    2020-10-12 11:40:31,736 stacktrace       L0045 ERROR|     True, shift, args, 
> > replay_path)
> >    2020-10-12 11:40:31,736 stacktrace       L0045 ERROR|   File 
> > "/home/alex.bennee/lsrc/qemu.git/builds/bisect/tests/acceptance/replay_kernel.py",
> >  line 57, in run_vm
> >    2020-10-12 11:40:31,736 stacktrace       L0045 ERROR|     vm.shutdown()
> >    2020-10-12 11:40:31,736 stacktrace       L0045 ERROR|   File 
> > "/home/alex.bennee/lsrc/qemu.git/python/qemu/machine.py", line 465, in shutdown
> >    2020-10-12 11:40:31,736 stacktrace       L0045 ERROR|     
> > self._do_shutdown(timeout, has_quit)
> >    2020-10-12 11:40:31,736 stacktrace       L0045 ERROR|   File 
> > "/home/alex.bennee/lsrc/qemu.git/python/qemu/machine.py", line 439, in 
> > _do_shutdown
> >    2020-10-12 11:40:31,736 stacktrace       L0045 ERROR|     from exc
> >    2020-10-12 11:40:31,737 stacktrace       L0045 ERROR| 
> > qemu.machine.AbnormalShutdown: Could not perform graceful shutdown
> >
> > The commit before:
> >
> >    2020-10-12 11:44:02,803 __init__         L0085 DEBUG| [    3.897837] md: ... 
> > autorun DONE.
> >    2020-10-12 11:44:02,806 __init__         L0085 DEBUG| [    3.897958] VFS: Cannot open 
> > root device "(null)" or unknown-block(0,0): error -6
> >    2020-10-12 11:44:02,806 qmp              L0245 DEBUG| >>> {'execute': 'quit'}
> >    2020-10-12 11:44:02,814 qmp              L0250 DEBUG| <<< {'return': {}}
> >    2020-10-12 11:44:02,879 replay_kernel    L0059 INFO | finished the recording 
> > with log size 237596 bytes
> >    2020-10-12 11:44:02,879 replay_kernel    L0064 INFO | elapsed time 24.35 sec
> >    2020-10-12 11:44:02,888 replay_kernel    L0044 INFO | replaying the 
> > execution...
> >    2020-10-12 11:44:02,889 machine          L0362 DEBUG| VM launch command: 
> > './qemu-system-arm -display none -vga none -chardev 
> > socket,id=mon,path=/var/tmp/tmpihqswp6_/qemu-7747-monitor.sock -mon 
> > chardev=mon,mode=control -machine virt -chardev 
> > socket,id=console,path=/var/tmp/tmpihqswp6_/qemu-7747-console.sock,server,nowait
> >  -serial chardev:console
> >    -icount 
> > shift=1,rr=replay,rrfile=/var/tmp/avocado_o3pfy2he/avocado_job_nf30vjqg/1-tests_acceptance_replay_kernel.py_ReplayKernel.test_arm_virt/replay.bin
> >  -kernel 
> > /home/alex.bennee/avocado/data/cache/by_location/62750ce9e069e69e6a7ff04ff54c382ee660b92a/vmlinuz
> >  -append printk.time=1 panic=-1 console=ttyAMA0 -net none -no-reboot'
> >    2020-10-12 11:44:03,001 qmp              L0245 DEBUG| >>> {'execute': 
> > 'qmp_capabilities'}
> >    2020-10-12 11:44:03,172 qmp              L0250 DEBUG| <<< {'return': {}}
> >    2020-10-12 11:44:04,899 __init__         L0085 DEBUG| [    0.000000] Booting 
> > Linux on physical CPU 0x0
> >    2020-10-12 11:44:04,904 __init__         L0085 DEBUG| [    0.000000] Linux 
> > version 4.18.16-300.fc29.armv7hl 
> > (mockbuild@buildvm-armv7-06.arm.fedoraproject.org) (gcc version 8.2.1 20180801 
> > (Red Hat 8.2.1-2) (GCC)) #1 SMP Sun Oct 21 00:56:28 UTC 2018
[...]