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

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

[Thomas Huth]

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(-)

diff --git a/tests/avocado/reverse_debugging.py b/tests/avocado/reverse_debugging.py
index fc47874eda..2585c78f34 100644
--- a/tests/avocado/reverse_debugging.py
+++ b/tests/avocado/reverse_debugging.py
@@ -11,6 +11,7 @@
 import logging
 
 from avocado import skipIf
+from avocado import skipUnless
 from avocado_qemu import BUILD_DIR
 from avocado.utils import gdb
 from avocado.utils import process
@@ -241,8 +242,8 @@ class ReverseDebugging_ppc64(ReverseDebugging):
 
     REG_PC = 0x40
 
-    # unidentified gitlab timeout problem
-    @skipIf(os.getenv('GITLAB_CI'), 'Running on GitLab')
+    # Test seems to be broken right now
+    @skipUnless(os.getenv('QEMU_TEST_FLAKY_TESTS'), 'Test gets stuck')
     def test_ppc64_pseries(self):
         """
         :avocado: tags=arch:ppc64
@@ -254,7 +255,7 @@ def test_ppc64_pseries(self):
         self.endian_is_le = False
         self.reverse_debugging()
 
-    @skipIf(os.getenv('GITLAB_CI'), 'Running on GitLab')
+    @skipUnless(os.getenv('QEMU_TEST_FLAKY_TESTS'), 'Test often fails')
     def test_ppc64_powernv(self):
         """
         :avocado: tags=arch:ppc64
-- 
2.41.0

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

[Philippe Mathieu-Daudé]

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(-)

Acked-by: Philippe Mathieu-Daudé <philmd@linaro.org>

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

[Philippe Mathieu-Daudé]

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?

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

[Thomas Huth]

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?

  Thomas

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

[Nicholas Piggin]

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"), which causes this halfway through the test:

2023-11-15 10:37:04,600 stacktrace       L0045 ERROR| Traceback (most recent call last):
2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|   File "/home/npiggin/src/qemu/build/pyvenv/lib/python3.11/site-packages/avocado/core/decorators.py", line 90, in wrapper
2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|     return function(obj, *args, **kwargs)
2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|   File "/home/npiggin/src/qemu/build/tests/avocado/reverse_debugging.py", line 264, in test_ppc64_powernv
2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|     self.reverse_debugging()
2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|   File "/home/npiggin/src/qemu/build/tests/avocado/reverse_debugging.py", line 173, in reverse_debugging
2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|     g.cmd(b'c')
2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|   File "/home/npiggin/src/qemu/build/pyvenv/lib/python3.11/site-packages/avocado/utils/gdb.py", line 783, in cmd
2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|     response_payload = self.decode(result)
2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|                        ^^^^^^^^^^^^^^^^^^^
2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|   File "/home/npiggin/src/qemu/build/pyvenv/lib/python3.11/site-packages/avocado/utils/gdb.py", line 738, in decode
2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|     raise InvalidPacketError
2023-11-15 10:37:04,600 stacktrace       L0045 ERROR| avocado.utils.gdb.InvalidPacketError
2023-11-15 10:37:04,600 stacktrace       L0046 ERROR|

It doesn't always fail the same gdb command
(I saw a bc on line 182 as well). It seems to be receiving a
zero length response?

No idea what's happening or why ppc seems to be more fragile.
Or why changing console connection affects gdb connection?

Thanks,
Nick

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

[Thomas Huth]

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?

  Thomas


> which causes this halfway through the test:
> 
> 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR| Traceback (most recent call last):
> 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|   File "/home/npiggin/src/qemu/build/pyvenv/lib/python3.11/site-packages/avocado/core/decorators.py", line 90, in wrapper
> 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|     return function(obj, *args, **kwargs)
> 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
> 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|   File "/home/npiggin/src/qemu/build/tests/avocado/reverse_debugging.py", line 264, in test_ppc64_powernv
> 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|     self.reverse_debugging()
> 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|   File "/home/npiggin/src/qemu/build/tests/avocado/reverse_debugging.py", line 173, in reverse_debugging
> 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|     g.cmd(b'c')
> 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|   File "/home/npiggin/src/qemu/build/pyvenv/lib/python3.11/site-packages/avocado/utils/gdb.py", line 783, in cmd
> 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|     response_payload = self.decode(result)
> 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|                        ^^^^^^^^^^^^^^^^^^^
> 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|   File "/home/npiggin/src/qemu/build/pyvenv/lib/python3.11/site-packages/avocado/utils/gdb.py", line 738, in decode
> 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|     raise InvalidPacketError
> 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR| avocado.utils.gdb.InvalidPacketError
> 2023-11-15 10:37:04,600 stacktrace       L0046 ERROR|
> 
> It doesn't always fail the same gdb command
> (I saw a bc on line 182 as well). It seems to be receiving a
> zero length response?
> 
> No idea what's happening or why ppc seems to be more fragile.
> Or why changing console connection affects gdb connection?
> 
> Thanks,
> Nick
> 

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

[Daniel P. Berrangé]

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.

> > which causes this halfway through the test:
> > 
> > 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR| Traceback (most recent call last):
> > 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|   File "/home/npiggin/src/qemu/build/pyvenv/lib/python3.11/site-packages/avocado/core/decorators.py", line 90, in wrapper
> > 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|     return function(obj, *args, **kwargs)
> > 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
> > 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|   File "/home/npiggin/src/qemu/build/tests/avocado/reverse_debugging.py", line 264, in test_ppc64_powernv
> > 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|     self.reverse_debugging()
> > 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|   File "/home/npiggin/src/qemu/build/tests/avocado/reverse_debugging.py", line 173, in reverse_debugging
> > 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|     g.cmd(b'c')
> > 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|   File "/home/npiggin/src/qemu/build/pyvenv/lib/python3.11/site-packages/avocado/utils/gdb.py", line 783, in cmd
> > 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|     response_payload = self.decode(result)
> > 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|                        ^^^^^^^^^^^^^^^^^^^
> > 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|   File "/home/npiggin/src/qemu/build/pyvenv/lib/python3.11/site-packages/avocado/utils/gdb.py", line 738, in decode
> > 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR|     raise InvalidPacketError
> > 2023-11-15 10:37:04,600 stacktrace       L0045 ERROR| avocado.utils.gdb.InvalidPacketError
> > 2023-11-15 10:37:04,600 stacktrace       L0046 ERROR|
> > 
> > It doesn't always fail the same gdb command
> > (I saw a bc on line 182 as well). It seems to be receiving a
> > zero length response?
> > 
> > No idea what's happening or why ppc seems to be more fragile.
> > Or why changing console connection affects gdb connection?

With regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

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

[Daniel P. Berrangé]

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.

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


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.

With regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

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

[Nicholas Piggin]

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) ? 

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

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

[Ani Sinha]

> On 15-Nov-2023, at 10:52 PM, Daniel P. Berrangé <berrange@redhat.com> 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.
> 
> 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
> 
> 
> 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.

As in https://gitlab.com/qemu-project/qemu/-/blob/master/tests/avocado/acpi-bits.py?ref_type=heads#L395 ?
Some other tests do this too.

>  
> 
> 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.
> 
> With regards,
> Daniel
> -- 
> |: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
> |: https://libvirt.org         -o-            https://fstop138.berrange.com :|
> |: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

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

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

[Thomas Huth]

On 16/11/2023 02.15, Nicholas Piggin 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:
...
>> 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) ?
> 
> 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

Tested-by: Thomas Huth <thuth@redhat.com>

Could you please send this as a proper patch, with a S-o-b line, and a short 
comment in front of the newly added code explaining it?

  Thanks,
   Thomas

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

[Nicholas Piggin]

On Thu Nov 16, 2023 at 1:55 PM AEST, Ani Sinha wrote:
>
>
> > 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. 

Hmm... well we do have QEMUMachine.set_console already. Is this enough?
If the test case is not going to drain or interact with the console
then it could set it to false. Or am I missing something?

Thanks,
Nick

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

[Daniel P. Berrangé]

On Thu, Nov 16, 2023 at 05:14:43PM +1000, Nicholas Piggin wrote:
> On Thu Nov 16, 2023 at 1:55 PM AEST, Ani Sinha wrote:
> >
> >
> > > 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. 
> 
> Hmm... well we do have QEMUMachine.set_console already. Is this enough?
> If the test case is not going to drain or interact with the console
> then it could set it to false. Or am I missing something?

Yeah, set_console is enough - i missed that that exists.

Thus problem is more specific. It hits when a test calls
set_console(True), but then fails to read from the console.


With regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

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

[Daniel P. Berrangé]

On Thu, Nov 16, 2023 at 11:15:25AM +1000, Nicholas Piggin 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?

There's no empty response - avocado is sending SIGTERM to the
test because no response ever arrived after 10 seconds 

> > @@ -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?

Yes, that's exactly it - the ppc firmware is very verbose, so is enough
to tip it over the limit.

> > 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) ? 
> 
> 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

Yes, thus should do the trick.

With regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

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

[Nicholas Piggin]

On Thu Nov 16, 2023 at 5:09 PM AEST, Thomas Huth wrote:
> On 16/11/2023 02.15, Nicholas Piggin 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:
> ...
> >> 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) ?
> > 
> > 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
>
> Tested-by: Thomas Huth <thuth@redhat.com>

Thank you.

> Could you please send this as a proper patch, with a S-o-b line, and a short 
> comment in front of the newly added code explaining it?

Yep, just testing it now. Should have it sent out in an hour or two.

Thanks,
Nick

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

[Ani Sinha]

> On 16-Nov-2023, at 2:25 PM, Daniel P. Berrangé <berrange@redhat.com> wrote:
> 
> On Thu, Nov 16, 2023 at 05:14:43PM +1000, Nicholas Piggin wrote:
>> On Thu Nov 16, 2023 at 1:55 PM AEST, Ani Sinha wrote:
>>> 
>>> 
>>>> 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. 
>> 
>> Hmm... well we do have QEMUMachine.set_console already. Is this enough?
>> If the test case is not going to drain or interact with the console
>> then it could set it to false. Or am I missing something?
> 
> Yeah, set_console is enough - i missed that that exists.
> 
> Thus problem is more specific. It hits when a test calls
> set_console(True), but then fails to read from the console.

So then it is a test issue in that the test requests console to be enabled but does not look at the console o/p.

> 
> 
> With regards,
> Daniel
> -- 
> |: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
> |: https://libvirt.org         -o-            https://fstop138.berrange.com :|
> |: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

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

[Daniel P. Berrangé]

On Thu, Nov 16, 2023 at 04:47:48PM +0530, Ani Sinha wrote:
> 
> 
> > On 16-Nov-2023, at 2:25 PM, Daniel P. Berrangé <berrange@redhat.com> wrote:
> > 
> > On Thu, Nov 16, 2023 at 05:14:43PM +1000, Nicholas Piggin wrote:
> >> On Thu Nov 16, 2023 at 1:55 PM AEST, Ani Sinha wrote:
> >>> 
> >>> 
> >>>> 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:
> >>>>> 
> >>>>> 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. 
> >> 
> >> Hmm... well we do have QEMUMachine.set_console already. Is this enough?
> >> If the test case is not going to drain or interact with the console
> >> then it could set it to false. Or am I missing something?
> > 
> > Yeah, set_console is enough - i missed that that exists.
> > 
> > Thus problem is more specific. It hits when a test calls
> > set_console(True), but then fails to read from the console.
> 
> So then it is a test issue in that the test requests console to be enabled but does not look at the console o/p.

Yes, any test cases affected by this are broken already, and need to drain
the console. We might easily miss if we only test with x86_64 QEMU and not
other arches, as eg ppc firmware appears more chatty on serial port than
seabios

With regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

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

[John Snow]

On Wed, Nov 15, 2023 at 12:23 PM Daniel P. Berrangé <berrange@redhat.com> 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.
>
> 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
>
>
> 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.

Tch. I see. Thank you for diagnosing this.

From the machine.py perspective, you have to *opt in* to having a
console, so I hadn't considered that a caller would enable the console
and then ... not read from it. Surely that's a bug in the caller?

If you don't intend to read from the console, you shouldn't call set_console().

(The async rewrite I have been toying with on and off has a built-in
drainer that writes to a log file that would probably remedy this, but
the client tests should still be fixed, I think. Otherwise, do you
have any suggestions for how I might make this failure state more
obvious/friendly? I wonder if on close of the machine.py object I
could detect that the pipe is full and emit a warning about that.)

--js

>
> With regards,
> Daniel
> --
> |: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
> |: https://libvirt.org         -o-            https://fstop138.berrange.com :|
> |: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|
>

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

[Nicholas Piggin]

On Tue Nov 21, 2023 at 5:18 AM AEST, John Snow wrote:
> On Wed, Nov 15, 2023 at 12:23 PM Daniel P. Berrangé <berrange@redhat.com> 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.
> >
> > 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
> >
> >
> > 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.
>
> Tch. I see. Thank you for diagnosing this.
>
> From the machine.py perspective, you have to *opt in* to having a
> console, so I hadn't considered that a caller would enable the console
> and then ... not read from it. Surely that's a bug in the caller?
>
> If you don't intend to read from the console, you shouldn't call set_console().

Agree, hence the fix patch for the test case.

Although most tests wait for console, ones like this that control the
machine with gdb/qmp are rarer, so less examples to copy paste from.

>
> (The async rewrite I have been toying with on and off has a built-in
> drainer that writes to a log file that would probably remedy this, but
> the client tests should still be fixed, I think. Otherwise, do you

This sounds good because no matter the test, you rarely don't want to
log console output. Separating that from what the test does with
console would be nice.

> have any suggestions for how I might make this failure state more
> obvious/friendly? I wonder if on close of the machine.py object I
> could detect that the pipe is full and emit a warning about that.)

That's an idea. It wouldn't be foolproof (test could be waiting for
something else or failed for some other reason), but at least it could
give a suggestion (similar to my warning in the chardev code).

How would you do it? Maybe the simplest/portable way would be keep
a pipe write fd open in the harness and try write something to it
with O_NONBLOCK?

Thanks,
Nick

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

[Peter Maydell]

On Mon, 20 Nov 2023 at 19:19, John Snow <jsnow@redhat.com> wrote:
>
> On Wed, Nov 15, 2023 at 12:23 PM Daniel P. Berrangé <berrange@redhat.com> wrote:
> > 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.

> > 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.
>
> Tch. I see. Thank you for diagnosing this.
>
> From the machine.py perspective, you have to *opt in* to having a
> console, so I hadn't considered that a caller would enable the console
> and then ... not read from it. Surely that's a bug in the caller?

From an Avocado test perspective, I would expect that the test case
should have to explicitly opt *out* of "the console messages appear
in the avocado test log, even if the test case doesn't care about them
for the purposes of identifying when to end the test or whatever".
The console logs are important for after-the-fact human diagnosis
of why a test might have failed, so we should always collect them.

thanks
-- PMM

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

[John Snow]

On Thu, Nov 23, 2023 at 5:53 AM Peter Maydell <peter.maydell@linaro.org> wrote:
>
> On Mon, 20 Nov 2023 at 19:19, John Snow <jsnow@redhat.com> wrote:
> >
> > On Wed, Nov 15, 2023 at 12:23 PM Daniel P. Berrangé <berrange@redhat.com> wrote:
> > > 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.
>
> > > 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.
> >
> > Tch. I see. Thank you for diagnosing this.
> >
> > From the machine.py perspective, you have to *opt in* to having a
> > console, so I hadn't considered that a caller would enable the console
> > and then ... not read from it. Surely that's a bug in the caller?
>
> From an Avocado test perspective, I would expect that the test case
> should have to explicitly opt *out* of "the console messages appear
> in the avocado test log, even if the test case doesn't care about them
> for the purposes of identifying when to end the test or whatever".
> The console logs are important for after-the-fact human diagnosis
> of why a test might have failed, so we should always collect them.
>
> thanks
> -- PMM
>

Understood. In that case, fixing the test would involve engaging's the
avocado suite's draining utility to ensure that the log is being
consumed and logged.

I think there's a potential here to simplify all of the
draining-and-logging code we have split across the avocado test suite,
console_socket.py and machine.py, but I can't promise that the rewrite
I've been working on will be ready quickly, so if this is still busted
(I'm still catching back up with my mail post-holidays) then we want a
quicker fix if we haven't committed one yet.

--js