Re: [PATCH v2 1/4] tests/functional: Introduce _console_read()

["Daniel P. Berrangé" <berrange@redhat.com>]

On Tue, Nov 12, 2024 at 02:02:43PM +0100, Cédric Le Goater wrote:
> Interaction with the console has been a problem in our avocado
> tests. In some cases, the expected string does not match in the
> output, causing the test to fail with a timeout. These were worked
> around by sleeping before reading the console and even with SSH
> connections in some places.
> 
> To fix, process the console output char by char and not with
> readline. This routine was largely inspired by console_wait() in
> tests/vm/basevm.py.
> 
> Signed-off-by: Cédric Le Goater <clg@redhat.com>
> ---
>  tests/functional/qemu_test/cmd.py | 22 ++++++++++++++++++++--
>  1 file changed, 20 insertions(+), 2 deletions(-)
> 
> diff --git a/tests/functional/qemu_test/cmd.py b/tests/functional/qemu_test/cmd.py
> index cbabb1ceed3c..5bca29d1d721 100644
> --- a/tests/functional/qemu_test/cmd.py
> +++ b/tests/functional/qemu_test/cmd.py
> @@ -12,6 +12,7 @@
>  # later.  See the COPYING file in the top-level directory.
>  
>  import logging
> +import re
>  import os
>  import os.path
>  import subprocess
> @@ -78,6 +79,23 @@ def run_cmd(args):
>  def is_readable_executable_file(path):
>      return os.path.isfile(path) and os.access(path, os.R_OK | os.X_OK)
>  
> +def _console_read(vm, expect):
> +    console_logger = logging.getLogger('console')
> +    output = ""
> +    while True:
> +        data = vm.console_socket.recv(1)
> +        if not data:
> +            break
> +        output += data.decode("latin1")

Decoding this as 'latin1' is going to mangle any output
that is not represented by a single-byte UTF-8 codepoint.

You can't simply switch this to 'utf8' though, as in the
socket.recv(1) call you're only reading a single byte,
and you can't guarantee that can be decoded if its part
of a multi-byte sequence.

I think you need to read into a bytearray, instead of
reading into a string. Then convert 'expect' into a
bytearray too, and compare bytes for a match, thus
avoiding problem of partial utf8 sequence decoding
errors.

> +        if expect in output:
> +            break
> +        if "\r" in output or "\n" in output:
> +            lines = re.split("[\r\n]", output)
> +            if lines[0]:
> +                console_logger.debug(lines[0])
> +            output = lines.pop()
> +    return output

In the commit message you talk about a problem with non-matched
text, and timeouts causing failure.

IIUC, the key difference between this code and the use of readline()
is that this code is checking for a match in the partial line. ie we
don't need to wait for a newline to arrive anymore.

That's an interesting difference, but its not obviously correlated
with the commit message description.

> +
>  def _console_interaction(test, success_message, failure_message,
>                           send_string, keep_sending=False, vm=None):
>      assert not keep_sending or send_string
> @@ -98,12 +116,12 @@ def _console_interaction(test, success_message, failure_message,
>              continue
>  
>          try:
> -            msg = console.readline().decode().strip()
> +            msg = _console_read(vm, success_message)
>          except UnicodeDecodeError:
>              msg = None
>          if not msg:
>              continue
> -        console_logger.debug(msg)
> +        console_logger.debug('found "%s"', msg)
>          if success_message is None or success_message in msg:
>              break
>          if failure_message and failure_message in msg:
> -- 
> 2.47.0
> 
> 

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 :|