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

[Philippe Mathieu-Daudé]

On 6/17/20 7:13 PM, Philippe Mathieu-Daudé wrote:
> On 6/16/20 11:49 PM, Cleber Rosa wrote:
>> 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?
>>>
>>
>> John's description seems spot on, and so does the solution.  I was
>> unable, though, to reproduce it given that the window is indeed tiny.

Still doesn't work...
https://travis-ci.org/github/philmd/qemu/jobs/700309163#L5445

>>
>> Phil,
>>
>> In addition to this, wouldn't it make sense to:
>>
>> diff --git a/tests/acceptance/boot_linux_console.py 
>> b/tests/acceptance/boot_linux_console.py
>> index 3d02519660..e117597e3b 100644
>> --- a/tests/acceptance/boot_linux_console.py
>> +++ b/tests/acceptance/boot_linux_console.py
>> @@ -180,8 +180,8 @@ class BootLinuxConsole(LinuxKernelTest):
>>                                 + 'rdinit=/sbin/init noreboot')
>>          self.vm.add_args('-kernel', kernel_path,
>>                           '-initrd', initrd_path,
>> -                         '-append', kernel_command_line,
>> -                         '-no-reboot')
>> +                         '-append', kernel_command_line)
> 
> Very few machines implement the hardware shutdown (sending
> the SHUTDOWN_CAUSE_GUEST_SHUTDOWN event). AFAIK The
> SHUTDOWN_CAUSE_GUEST_RESET is a bit more present.
> When the hardware doesn't model this, the guest loops
> infinitely. Some physical machines are not supposed to
> power off, until cutting its power. So firmware also loops
> without trying to power things off.
> 
> '-no-reboot' means "if the guest tries to reboot, consider
> the emulation done".
> 
>> +
>>          self.vm.launch()
>>          self.wait_for_console_pattern('Boot successful.')
>>  
>> @@ -189,8 +189,8 @@ class BootLinuxConsole(LinuxKernelTest):
>>                                                  'BogoMIPS')
>>          exec_command_and_wait_for_pattern(self, 'uname -a',
>>                                                  'Debian')
>> -        exec_command_and_wait_for_pattern(self, 'reboot',
>> -                                                'reboot: Restarting system')
>> +        exec_command_and_wait_for_pattern(self, 'halt',
>> +                                                'reboot: System halted')
>>  
>>      @skipUnless(os.getenv('AVOCADO_ALLOW_UNTRUSTED_CODE'), 'untrusted code')
>>      def test_mips64el_malta_5KEc_cpio(self):
>>
>> Do you know of any reason to "fake halt" (reboot) instead of actually
>> halting from the guests?
> 
> This might be my embedded system reflex (explained earlier, some
> hardware can not power itself down). I will give your diff a try.
> 
>>
>>>>              self._qmp.close()
>>>>
>>>>          self._popen.wait(timeout=timeout)
>>>>
>>>
>>
>> Either way (^ with this extra block):
>>
>> Reviewed-by: Cleber Rosa <crosa@redhat.com>
>> Tested-by: Cleber Rosa <crosa@redhat.com>
> 
> Thanks!
>