Cédric Le Goater <c...@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.ben...@linaro.org>
>> Reviewed-by: Philippe Mathieu-Daudé <phi...@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
