On Mon, Jun 15, 2020 at 05:21:18PM +0200, Philippe Mathieu-Daudé wrote: > On 6/9/20 11:55 PM, John Snow wrote: > > > > > > On 6/9/20 9:08 AM, Philippe Mathieu-Daudé wrote: > >> Hi John, > >> > >> On 6/4/20 9:52 PM, John Snow wrote: > >>> v3: > >>> - Split _post_shutdown refactor into own patch (now 1/3) > >>> - Re-add sigkill warning squelch (now 3/3) > >>> > >>> NOTE: I re-added the squelch in its own patch for review purposes, but > >>> for the purposes of avoiding temporary breakage, a maintainer may wish > >>> to squash patches 2 and 3 if they are accepted. > >>> > >>> v2: Philippe took patches 1, 3 and 4. > >>> > >>> This is a re-write of what was: > >>> [PATCH RFC 03/32] python//machine.py: remove bare except > >>> [PATCH 2/4] python/machine.py: remove bare except > >>> > >>> It's a bit heavier handed, but it should address some of kwolf's > >>> feedback from the RFC version. > >>> > >>> Applies straight to origin/master, ought to pass pylint and flake8: > >>> > >>>> cd ~/src/qemu/python/qemu > >>>> pylint *.py > >>>> flake8 *.py > >>> > >>> John Snow (3): > >>> python/machine.py: consolidate _post_shutdown() > >>> python/machine.py: refactor shutdown > >>> python/machine.py: re-add sigkill warning suppression > >>> > >>> python/qemu/machine.py | 100 +++++++++++++++++++++++++++++------------ > >>> 1 file changed, 71 insertions(+), 29 deletions(-) > >>> > >> > >> I'm now seeing this error: > >> > >> 21:31:58 DEBUG| / # reboot > >> 21:32:01 DEBUG| / # reboot: Restarting system > >> 21:32:01 DEBUG| >>> {'execute': 'quit'} > >> 21:32:01 WARNI| qemu received signal 9; command: > >> "mips-softmmu/qemu-system-mips -display none -vga none -chardev > >> socket,id=mon,path=/tmp/tmp679upvrk/qemu-10292-monitor.sock -mon > >> chardev=mon,mode=control -machine malta -chardev > >> socket,id=console,path=/tmp/tmp679upvrk/qemu-10292-console.sock,server,nowait > >> -serial chardev:console -kernel > >> /tmp/avocado_b3aaagr9/avocado_job_5bj0xe1h/12-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_mips_malta_cpio/boot/vmlinux-4.5.0-2-4kc-malta > >> -initrd > >> /tmp/avocado_b3aaagr9/avocado_job_5bj0xe1h/12-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_mips_malta_cpiorootfs.cpio > >> -append printk.time=0 console=ttyS0 console=tty rdinit=/sbin/init > >> noreboot -no-reboot" > >> 21:32:01 ERROR| > >> 21:32:01 ERROR| Reproduced traceback from: > >> /home/travis/build/philmd/qemu/build/tests/venv/lib/python3.6/site-packages/avocado/core/test.py:886 > >> 21:32:01 ERROR| Traceback (most recent call last): > >> 21:32:01 ERROR| File > >> "/home/travis/build/philmd/qemu/build/tests/acceptance/avocado_qemu/__init__.py", > >> line 195, in tearDown > >> 21:32:01 ERROR| vm.shutdown() > >> 21:32:01 ERROR| File > >> "/home/travis/build/philmd/qemu/python/qemu/machine.py", line 449, in > >> shutdown > >> 21:32:01 ERROR| self._do_shutdown(has_quit) > >> 21:32:01 ERROR| File > >> "/home/travis/build/philmd/qemu/python/qemu/machine.py", line 426, in > >> _do_shutdown > >> 21:32:01 ERROR| self._soft_shutdown(has_quit, timeout) > >> 21:32:01 ERROR| File > >> "/home/travis/build/philmd/qemu/python/qemu/machine.py", line 413, in > >> _soft_shutdown > >> 21:32:01 ERROR| self._qmp.cmd('quit') > >> 21:32:01 ERROR| File > >> "/home/travis/build/philmd/qemu/python/qemu/qmp.py", line 271, in cmd > >> 21:32:01 ERROR| return self.cmd_obj(qmp_cmd) > >> 21:32:01 ERROR| File > >> "/home/travis/build/philmd/qemu/python/qemu/qmp.py", line 249, in cmd_obj > >> 21:32:01 ERROR| > >> self.__sock.sendall(json.dumps(qmp_cmd).encode('utf-8')) > >> 21:32:01 ERROR| BrokenPipeError: [Errno 32] Broken pipe > >> 21:32:01 ERROR| > >> 21:32:01 DEBUG| DATA (filename=output.expected) => NOT FOUND (data > >> sources: variant, test, file) > >> 21:32:01 DEBUG| DATA (filename=stdout.expected) => NOT FOUND (data > >> sources: variant, test, file) > >> 21:32:01 DEBUG| DATA (filename=stderr.expected) => NOT FOUND (data > >> sources: variant, test, file) > >> 21:32:01 DEBUG| Not logging /var/log/syslog (lack of permissions) > >> 21:32:01 ERROR| ERROR > >> 12-tests/acceptance/boot_linux_console.py:BootLinuxConsole.test_mips_malta_cpio > >> -> TestSetupFail: [Errno 32] Broken pipe > >> 21:32:01 INFO | > >> > >> https://travis-ci.org/github/philmd/qemu/jobs/696142277#L5329 > >> > > > > Gotcha. > > > > The problem here is that `test_mips_malta_cpio` in boot_linux_console.py > > does this: > > > > self.vm.add_args('-kernel', kernel_path, > > '-initrd', initrd_path, > > '-append', kernel_command_line, > > '-no-reboot') > > > > and then: > > > > exec_command_and_wait_for_pattern(self, 'reboot', > > 'reboot: Restarting system') > > > > and (in avocado_qemu/) __init__.py does this: > > > > def tearDown(self): > > for vm in self._vms.values(): > > vm.shutdown() > > > > > > > > What's happening here is that we are instructing QEMU to *close* when > > the guest reboots instead of allowing it to reboot. Then, we are issuing > > a reboot command to the guest, which will effectively terminate QEMU as > > well. Finally, we are trying to send a shutdown command to QEMU, but > > QEMU has already gone. > > > > Now, in the shutdown code, we do make an attempt to catch this: > > > > def is_running(self): > > """Returns true if the VM is running.""" > > return self._popen is not None and self._popen.poll() is None > > > > But, well, race conditions. > > > > When we make it here: > > > > if self._qmp is not None: > > if not has_quit: > > self._qmp.cmd('quit') > > self._qmp.close() > > > > We believe we are running and we believe we have an open QMP socket. > > Attempting to engage the socket by sending 'quit' causes the error. > > > > It's a tight window: if quit happens earlier, we send the command > > successfully and everything's OK. If quit happens later, we realize QEMU > > isn't running and proceed to cleanup. > > Nice debugging :) > > > > > Ultimately: > > > > - Avocado should not try to shut down QEMU twice, but > > - machine.py shouldn't enable the race condition either. > > > > > > > > for my part, how about this: > > > > diff --git a/python/qemu/machine.py b/python/qemu/machine.py > > index 99bcb499878..813f8e477db 100644 > > --- a/python/qemu/machine.py > > +++ b/python/qemu/machine.py > > @@ -385,7 +385,14 @@ def _soft_shutdown(self, has_quit: bool = False, > > timeout: int = 3) -> None: > > > > if self._qmp is not None: > > if not has_quit: > > - self._qmp.cmd('quit') > > + try: > > + self._qmp.cmd('quit') > > + except (BrokenPipeError, ConnectionResetError): > > + # QMP went away just before or just after sending > > 'quit' > > + if not self.is_running(): > > + # "Mission Accomplished" > > + pass > > + raise > > Looks OK to me, Cleber/Eduardo can you Ack?
Looks good to me. Reviewed-by: Eduardo Habkost <ehabk...@redhat.com> > > > self._qmp.close() > > > > self._popen.wait(timeout=timeout) > > > -- Eduardo