Re: [PATCH v3 0/3] python/machine.py: refactor shutdown

[John Snow]

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.

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
             self._qmp.close()

         self._popen.wait(timeout=timeout)