Re: [PATCH v2 02/12] tests/avocado: improve behaviour waiting for login prompts

["Alex Bennée" <alex.bennee@linaro.org>]

Cédric Le Goater <clg@kaod.org> writes:

> Hello Alex,
>
> On 11/11/22 15:55, Alex Bennée wrote:
>> This attempts to deal with the problem of login prompts not being
>> guaranteed to be terminated with a newline. The solution to this is to
>> peek at the incoming data looking to see if we see an up-coming match
>> before we fall back to the old readline() logic. The reason to mostly
>> rely on readline is because I am occasionally seeing the peek stalling
>> despite data being there.
>> This seems kinda hacky and gross so I'm open to alternative
>> approaches
>> and cleaner python code.
>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>> Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org>
>
> I have pulled this patch in the aspeed tree hoping it would improve tests:
>
>   AST2x00MachineSDK.test_arm_ast2500_evb_sdk
>   AST2x00MachineSDK.test_arm_ast2600_evb_sdk
>
> but the failure rate has increased :/ I have seen failures in these also :
>
>   AST2x00Machine.test_arm_ast2500_evb_buildroot
>   AST2x00Machine.test_arm_ast2600_evb_buildroot
>
> which used to be quite stable.
>
> Sorry, this is not of much help. the issue might be elsewhere.

Do you see what is happening in the logs? I've made a couple of tweaks
since and it gets through the negotiation but then timesout:

  console: looking for 22:(ast2600-default login:), sending None (always=False)
  /console: [    0.939039] aspeed-pcie 1e7700c0.pcie: [1] : tx idle timeout [0]
  -console: [    1.385144] spi-nor spi0.1: unrecognized JEDEC id bytes: 00 00 00 00 00 00
  console: [    1.413028] spi-nor spi2.0: unrecognized JEDEC id bytes: 00 00 00 00 00 00                                                                                       
  console: [    1.617539] aspeed-rtc 1e781000.rtc: hctosys: unable to read the hardware clock
  -console: rofs = mtd4 squashfs rwfs = mtd5 jffs2
  /console: [   14.563495] systemd[1]: Failed to find module 'autofs4'                  
  -console: [   18.034371] systemd[176]: /lib/systemd/system-generators/systemd-gpt-auto-generator failed with exit status 1.
  |console: [FAILED] Failed to start Intel Power Control for the Host 0.
  /console: [FAILED] Failed to start Phosphor C…istening on device /dev/ttyS2.
  console: [DEPEND] Dependency failed for Host logger for ttyS2.
  -console: Phosphor OpenBMC (Phosphor OpenBMC Project Reference Distro) nodistro.0 ast2600-default ttyS4
  console: ast2600-default login:
   (always=False)g for 9:(Password:), sending root
  console: root
  |console: Password:
   (always=False)g for 23:(root@ast2600-default:~#), sending 0penBmc
  console: Login timed out after 60 seconds.
  |console: Phosphor OpenBMC (Phosphor OpenBMC Project Reference Distro) nodistro.0 ast2600-default ttyS4
  /avocado.test:

>
> Thanks for the time you spend on this.
>
> C.
>
>
>> ---
>> v2
>>    - remove superfluous /r/n
>> ---
>>   tests/avocado/avocado_qemu/__init__.py | 89 +++++++++++++++++++++++++-
>>   1 file changed, 88 insertions(+), 1 deletion(-)
>> diff --git a/tests/avocado/avocado_qemu/__init__.py
>> b/tests/avocado/avocado_qemu/__init__.py
>> index 910f3ba1ea..20cba57161 100644
>> --- a/tests/avocado/avocado_qemu/__init__.py
>> +++ b/tests/avocado/avocado_qemu/__init__.py
>> @@ -131,6 +131,58 @@ def pick_default_qemu_bin(bin_prefix='qemu-system-', arch=None):
>>               return path
>>       return None
>>   +def _peek_ahead(console, min_match, success_message):
>> +    """
>> +    peek ahead in the console stream keeping an eye out for the
>> +    success message.
>> +
>> +    Returns some message to process or None, indicating the normal
>> +    readline should occur.
>> +    """
>> +    console_logger = logging.getLogger('console')
>> +    peek_len = 0
>> +    retries = 0
>> +
>> +    while True:
>> +        try:
>> +            old_peek_len = peek_len
>> +            peek_ahead = console.peek(min_match).decode()
>> +            peek_len = len(peek_ahead)
>> +
>> +            # if we get stuck too long lets just fallback to readline
>> +            if peek_len <= old_peek_len:
>> +                retries += 1
>> +                if retries > 10:
>> +                    return None
>> +
>> +            # if we see a newline in the peek we can let safely bail
>> +            # and let the normal readline() deal with it
>> +            if peek_ahead.endswith(('\n', '\r')):
>> +                return None
>> +
>> +            # if we haven't seen enough for the whole message but the
>> +            # first part matches lets just loop again
>> +            if len(peek_ahead) < min_match and \
>> +               success_message[:peek_len] in peek_ahead:
>> +                continue
>> +
>> +            # if we see the whole success_message we are done, consume
>> +            # it and pass back so we can exit to the user
>> +            if success_message in peek_ahead:
>> +                return console.read(peek_len).decode()
>> +
>> +            # of course if we've seen enough then this line probably
>> +            # doesn't contain what we are looking for, fallback
>> +            if peek_len > min_match:
>> +                return None
>> +
>> +        except UnicodeDecodeError:
>> +            console_logger.log("error in decode of peek")
>> +            return None
>> +
>> +    # we should never get here
>> +    return None
>> +
>>     def _console_interaction(test, success_message, failure_message,
>>                            send_string, keep_sending=False, vm=None):
>> @@ -139,17 +191,52 @@ def _console_interaction(test, success_message, failure_message,
>>           vm = test.vm
>>       console = vm.console_socket.makefile(mode='rb', encoding='utf-8')
>>       console_logger = logging.getLogger('console')
>> +
>> +    # Establish the minimum number of bytes we would need to
>> +    # potentially match against success_message
>> +    if success_message is not None:
>> +        min_match = len(success_message)
>> +    else:
>> +        min_match = 0
>> +
>> +    console_logger.debug("looking for %d:(%s), sending %s (always=%s)",
>> +                         min_match, success_message, send_string, keep_sending)
>> +
>>       while True:
>> +        msg = None
>> +
>> +        # First send our string, optionally repeating the send next
>> +        # cycle.
>>           if send_string:
>>               vm.console_socket.sendall(send_string.encode())
>>               if not keep_sending:
>>                   send_string = None # send only once
>> +
>> +        # If the console has no data to read we briefly
>> +        # sleep before continuing.
>> +        if not console.readable():
>> +            time.sleep(0.1)
>> +            continue
>> +
>>           try:
>> -            msg = console.readline().decode().strip()
>> +
>> +            # First we shall peek ahead for a potential match to cover waiting
>> +            # for lines without any newlines.
>> +            if min_match > 0:
>> +                msg = _peek_ahead(console, min_match, success_message)
>> +
>> +            # otherwise we block here for a full line
>> +            if not msg:
>> +                msg = console.readline().decode().strip()
>> +
>>           except UnicodeDecodeError:
>> +            console_logger.debug("skipped unicode error")
>>               msg = None
>> +
>> +        # if nothing came out we continue and try again
>>           if not msg:
>>               continue
>> +
>>           console_logger.debug(msg)
>>           if success_message is None or success_message in msg:
>>               break


-- 
Alex Bennée