Re: [PATCH] tests/avocado/reverse_debugging: Disable the ppc64 tests by default

[Ani Sinha]

> On 16-Nov-2023, at 6:45 AM, Nicholas Piggin <npiggin@gmail.com> wrote:
> 
> On Thu Nov 16, 2023 at 3:22 AM AEST, Daniel P. Berrangé wrote:
>> On Wed, Nov 15, 2023 at 01:14:53PM +0000, Daniel P. Berrangé wrote:
>>> On Wed, Nov 15, 2023 at 07:23:01AM +0100, Thomas Huth wrote:
>>>> On 15/11/2023 02.15, Nicholas Piggin wrote:
>>>>> On Wed Nov 15, 2023 at 4:29 AM AEST, Thomas Huth wrote:
>>>>>> On 14/11/2023 17.37, Philippe Mathieu-Daudé wrote:
>>>>>>> On 14/11/23 17:31, Thomas Huth wrote:
>>>>>>>> The tests seem currently to be broken. Disable them by default
>>>>>>>> until someone fixes them.
>>>>>>>> 
>>>>>>>> Signed-off-by: Thomas Huth <thuth@redhat.com>
>>>>>>>> ---
>>>>>>>>   tests/avocado/reverse_debugging.py | 7 ++++---
>>>>>>>>   1 file changed, 4 insertions(+), 3 deletions(-)
>>>>>>> 
>>>>>>> Similarly, I suspect https://gitlab.com/qemu-project/qemu/-/issues/1961
>>>>>>> which has a fix ready:
>>>>>>> https://lore.kernel.org/qemu-devel/20231110170831.185001-1-richard.henderson@linaro.org/
>>>>>>> 
>>>>>>> Maybe wait the fix gets in first?
>>>>>> 
>>>>>> No, I applied Richard's patch, but the problem persists. Does this test
>>>>>> still work for you?
>>>>> 
>>>>> I bisected it to 1d4796cd008373 ("python/machine: use socketpair() for
>>>>> console connections"),
>>>> 
>>>> Maybe John (who wrote that commit) can help?
>>> 
>>> I find it hard to believe this commit is a direct root cause of the
>>> problem since all it does is change the QEMU startup sequence so that
>>> instead of QEMU listening for a monitor connection, it is given a
>>> pre-opened monitor connection.
>>> 
>>> At the very most that should affect the startup timing a little.
>>> 
>>> I notice all the reverse debugging tests have a skip on gitlab
>>> with a comment:
>>> 
>>>    # unidentified gitlab timeout problem
>>> 
>>> this makes be suspicious that John's patch has merely made this
>>> (henceforth undiagnosed) timeout more likely to ocurr.
>> 
>> After an absolutely horrendous hours long debugging session I think
>> I figured out the problem. The QEMU process is blocking in
>> 
>>    qemu_chr_write_buffer
>> 
>> spinning in the loop on EAGAIN.
> 
> Great work.
> 
> Why does this make the gdb socket give an empty response? Something
> just times out?
> 
>> 
>> The Python  Machine() class has passed one of a pre-created socketpair
>> FDs for the serial port chardev. The guest is trying to write to this
>> and blocking.  Nothing in the Machine() class is reading from the
>> other end of the serial port console.
>> 
>> 
>> Before John's change, the serial port uses a chardev in server mode
>> and crucially  'wait=off', and the Machine() class never opened the
>> console socket unless the test case wanted to read from it.
>> 
>> IOW, QEMU had a background job setting there waiting for a connection
>> that would never come.
>> 
>> As a result when QEMU started executing the guest, all the serial port
>> writes get sent into to the void.
>> 
>> 
>> So John's patch has had a semantic change in behaviour, because the
>> console socket is permanently open, and thus socket buffers are liable
>> to fill up.
>> 
>> As a demo I increased the socket buffers to 1MB and everything then
>> succeeded.
>> 
>> @@ -357,6 +360,10 @@ def _pre_launch(self) -> None:
>> 
>>         if self._console_set:
>>             self._cons_sock_pair = socket.socketpair()
>> +            self._cons_sock_pair[0].setsockopt(socket.SOL_SOCKET, 
>> socket.SO_SNDBUF, 1024*1024);
>> +            self._cons_sock_pair[0].setsockopt(socket.SOL_SOCKET, 
>> socket.SO_RCVBUF, 1024*1024);
>> +            self._cons_sock_pair[1].setsockopt(socket.SOL_SOCKET, 
>> socket.SO_SNDBUF, 1024*1024);
>> +            self._cons_sock_pair[1].setsockopt(socket.SOL_SOCKET, 
>> socket.SO_RCVBUF, 1024*1024);
>>             os.set_inheritable(self._cons_sock_pair[0].fileno(), True)
>> 
>>         # NOTE: Make sure any opened resources are *definitely* freed in
> 
> So perhaps ppc64 fails just because it prints more to the console in early
> boot than other targets?
> 
>> The Machine class doesn't know if anything will ever use the console,
>> so as is the change is unsafe.
>> 
>> The original goal of John's change was to guarantee we capture early
>> boot messages as some test need that.  
>> 
>> I think we need to be able to have a flag to say whether the caller needs
>> an "early console" facility, and only use the pre-opened FD passing for
>> that case. Tests we need early console will have to ask for that guarantee
>> explicitly.
> 
> The below patch makes this test work. Maybe as a quick fix it is
> better than disabling the test.
> 
> I guess we still have a problem if a test invokes vm.launch()
> directly without subsequently waiting for a console pattern or
> doing something with the console as you say. Your suggesstion is
> add something like vm.launch(console=True) ? 

I think what he is saying is to add a new property for QEMUMachine() with which 
the test can explicitly tell the machine init code that it is going to drain 
the console logs. By default it can be false. When tests use console_drainer, 
they can set the property to true and inspect the early console logs after 
draining it. 

> 
> Thanks,
> Nick
> ---
> 
> diff --git a/tests/avocado/reverse_debugging.py 
> b/tests/avocado/reverse_debugging.py
> index fc47874eda..128d85bc0e 100644
> --- a/tests/avocado/reverse_debugging.py
> +++ b/tests/avocado/reverse_debugging.py
> @@ -12,6 +12,7 @@
> 
> from avocado import skipIf
> from avocado_qemu import BUILD_DIR
> +from avocado.utils import datadrainer
> from avocado.utils import gdb
> from avocado.utils import process
> from avocado.utils.network.ports import find_free_port
> @@ -52,6 +53,10 @@ def run_vm(self, record, shift, args, replay_path, 
> image_path, port):
>         if args:
>             vm.add_args(*args)
>         vm.launch()
> +        console_drainer = datadrainer.LineLogger(vm.console_socket.fileno(),
> +                                    logger=self.log.getChild('console'),
> +                                    stop_check=(lambda : not 
> vm.is_running()))
> +        console_drainer.start()
>         return vm
> 
>     @staticmethod